-
Notifications
You must be signed in to change notification settings - Fork 371
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Improvements in test logs #2792
Conversation
narrieta
commented
Mar 27, 2023
- Created individual logs for the setup of the test environments (previously they were written to the LISA log)
- Split the logs in directories: tests, environment setup, lisa, and vm_logs
- Removed duplicate junit test results for test failures (it used to show on the test results and on the LISA results)
Codecov Report
@@ Coverage Diff @@
## develop #2792 +/- ##
========================================
Coverage 72.01% 72.01%
========================================
Files 104 104
Lines 15870 15870
Branches 2273 2273
========================================
Hits 11429 11429
Misses 3916 3916
Partials 525 525 Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here. |
@@ -49,10 +49,13 @@ def type_schema(cls) -> Type[schema.TypedSchema]: | |||
|
|||
def _received_message(self, message: MessageBase) -> None: | |||
# The Agent sends its own TestResultMessage and marks them as "AgentTestResultMessage"; for the | |||
# test results sent by LISA itself, we change the suite name to "_Setup_" in order to separate them | |||
# test results sent by LISA itself, we change the suite name to "_Runbook_" in order to separate them |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Now the environment setup has its own log, so I am renaming this to "Runbook", this would capture any errors in LISA itself (before the agent code runs)
@@ -49,7 +50,7 @@ | |||
from tests_e2e.tests.lib.agent_test import TestSkipped | |||
from tests_e2e.tests.lib.agent_test_context import AgentTestContext | |||
from tests_e2e.tests.lib.identifiers import VmIdentifier | |||
from tests_e2e.tests.lib.logging import log as agent_test_logger # Logger used by the tests |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Initally most of the output was going to the LISA log, which was referenced as 'self.log', while the the test logs were referenced as 'agent_test_logger'.
Over time, most of the output has been moved to the test logs. Now the LISA log is references as 'self.lisa_log' and the test logs simply as 'log' (which makes this class consistent with the naming in the rest of the test code).
self.node: Node = None | ||
self.runbook_name: str = None | ||
self.image_name: str = None |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
the value in this variable is actually the environment name; renaming accordingly
@@ -129,12 +130,10 @@ def __init__(self, metadata: TestSuiteMetadata) -> None: | |||
# The context is initialized by _set_context() via the call to execute() | |||
self.__context: AgentTestSuite._Context = None | |||
|
|||
def _set_context(self, node: Node, variables: Dict[str, Any], lisa_log_path: str, log: Logger): | |||
def _initialize(self, node: Node, variables: Dict[str, Any], lisa_working_path: str, lisa_log_path: str, lisa_log: Logger): |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
renamed the method to make explicit that this initializes the AgentTestSuite
connection_info = node.connection_info | ||
node_context = get_node_context(node) | ||
runbook = node.capability.get_extended_runbook(AzureNodeSchema, AZURE) | ||
# Remove the resource group and node suffix, e.g. "e1-n0" in "lisa-20230110-162242-963-e1-n0" | ||
runbook_name = re.sub(r"-\w+-\w+$", "", runbook.name) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
this was use to create a unique directory name for the runbook; no longer needed
# Set the thread name to the name of the environment. The thread name is added to each item in LISA's log. | ||
with _set_thread_name(self.context.environment_name): | ||
log_path: Path = self.context.log_path/f"env-{self.context.environment_name}.log" | ||
with set_current_thread_log(log_path): |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
each environment now has its own log
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
sorry I'm really confused here, how many different sets of logs we have?
For example
self.context.lisa_log.info("Setting up test node")
log.info("")
The first log goes to main log which is gist of each step of the flow or only logs specific msgs?
The second is what you are calling environment log which has something like node step, installing test version logs etc..?
where about test scenario log goes? will it have separate log?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
@nagworld9 I'd recommend checking the artifacts in the test run to see each log and its contents
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
makes sense.
Basically log.info could be either test log or environment log depending on which thread under its being invoked.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Not quite.
We have multiple threads executing multiple environments, each environment executing multiple test suites. For each environment, we have an environment log and multiple test suite logs. If we had 3 environments executing 5 test suites each, we would have 3 environment logs + 3x5 test suite logs (total 18 logs, plus some other logs: the LISA log, the CheckAgentLog log, etc).
For each thread we have this nesting
log_path: Path = self.context.log_path/f"env-{self.context.environment_name}.log"
with set_current_thread_log(log_path):
....
log.info("GOES TO THE ENVIRONMENT LOG")
...
for suite in self.context.test_suites: # pylint: disable=E1133
....
log_path:Path = self.context.log_path/f"{suite_full_name}.log"
with set_current_thread_log(log_path):
....
log.info("GOES TO THE TEST SUITE LOG")
....
log.info("GOES TO THE ENVIRONMENT LOG AGAIN")
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
i.e the scope of the log is determined by the context manager in the with statement
TestStatus.FAILED, | ||
start_time, | ||
message=message + '\n' + '\n'.join([e.text for e in errors[0:3]])) | ||
except: # pylint: disable=bare-except |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
we were not handling exceptions raised while collecting the vm logs; now we are
|
||
return False | ||
|
||
@staticmethod |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Logs for test suites with errors are now prefixed with '_'
rm -r "$BUILD_ARTIFACTSTAGINGDIRECTORY"/lisa/[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9] | ||
mv "$BUILD_ARTIFACTSTAGINGDIRECTORY"/lisa/lisa-*.log "$BUILD_ARTIFACTSTAGINGDIRECTORY" | ||
rm "$BUILD_ARTIFACTSTAGINGDIRECTORY"/lisa/messages.log | ||
if ls "$LOGS_DIRECTORY"/env-*.log > /dev/null 2>&1; then |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
separated the logs into subdirectories:
- root directory: logs for tests with errors
- test_logs: logs for passing tests
- environment_logs: logs for environment (test VM) setup
- vm_logs: logs harvested from the VMs
- runbook_logs: logs global to the runbook (LISA log and junit results)
@@ -127,8 +145,11 @@ def set_current_thread_log(log_file: Path): | |||
""" | |||
Context Manager to set the log file for the current thread temporarily | |||
""" | |||
initial_value = log.get_current_thread_log() |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This allows nesting context managers
# Set the thread name to the name of the environment. The thread name is added to each item in LISA's log. | ||
with _set_thread_name(self.context.environment_name): | ||
log_path: Path = self.context.log_path/f"env-{self.context.environment_name}.log" | ||
with set_current_thread_log(log_path): |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
makes sense.
Basically log.info could be either test log or environment log depending on which thread under its being invoked.
@@ -51,7 +52,7 @@ def run(self): | |||
private_key_file: Path = self._context.working_directory/f"{username}_rsa" | |||
public_key_file: Path = self._context.working_directory/f"{username}_rsa.pub" | |||
log.info("Generating SSH key as %s", private_key_file) | |||
ssh: SshClient = SshClient(ip_address=self._context.vm_ip_address, username=username, private_key_file=private_key_file) | |||
ssh = SshClient(ip_address=self._context.vm_ip_address, username=username, private_key_file=private_key_file) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
why type removed?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
it's already declared on line 41
log.info("LISA Environment (for correlation with the LISA log): %s", environment.name) | ||
log.info("Runbook variables:") | ||
for name, value in variables.items(): | ||
log.info(" %s: %s", name, value if name != 'c_test_suites' else [t.name for t in value]) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
is extra space at the start intentional?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
yes, it adds a level of indentation that helps with readability