Skip to content
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鈥檒l occasionally send you account related emails.

Already on GitHub? Sign in to your account

Keep trace logs for failed tests #508

Merged
merged 5 commits into from
Oct 18, 2023
Merged

Conversation

acodrington
Copy link
Contributor

Background

Trace logs can provide us with invaluable information about Halibut when debugging problems, but unfortunately they are too verbose to be practical on the build server, as the extra logging causes the build logs to be prohibitively large.

This PR attempts to have the best of both worlds (info-level logs when everything is fine, trace-level logs when there are problems) by logging a test's trace logs to a separate log file which can be kept if the test fails.

Results

Fixes [sc-56164]

During the setup for each individual test (BaseTest.SetUp), a TraceLogFileLogger is created and passed to the SerilogLoggerBuilder when initializing the logger. This new class is responsible for writing logs to a temporary file, and copying that file to the build artifacts directory if needed.

Once the SerilogLoggerBuilder.Build method is called, the instance of TraceLogFileLogger is stored in memory for the currently running test and is utilised by a custom Serilog sink which will find and write to the appropriate trace logger for the current test each time a log message is sent.

After the test is completed, the teardown method (BaseTest.TearDown) will check the status of the test and have the TraceLogFileLogger copy the trace log file to the build artifacts if the test failed.

Trace log files are named {TestHash}.tracelog, where TestHash is a short Base64 hash based on the test name. This TestHash is also printed in the log output, allowing a developer to easily find the corresponding trace log file for any failed test.

Before

No trace logs for failed tests 馃槥

After

20231013-111756_firefox_pNkiCzwGe3

20231013-111549_firefox_Fje2qcr1nq

20231013-140855_jq5jSdEWB4

How to review this PR

Are there are any other tests or test base class which need to modified to log trace-level logs? I've modified the default for the IClientAndServiceBuilder implementations, but are there any tests that don't use these builders that need updating?

Pre-requisites

  • I have read How we use GitHub Issues for help deciding when and where it's appropriate to make an issue.
  • I have considered informing or consulting the right people, according to the ownership map.
  • I have considered appropriate testing for my change.

@acodrington acodrington requested a review from a team as a code owner October 13, 2023 06:15
@shortcut-integration
Copy link

Multiple test classes derived from the same base test class
can have duplicate test names i.e. tests in the base class
@acodrington acodrington force-pushed the sast/trace-logs-for-failed-tests branch from 3e243fc to e868dea Compare October 13, 2023 07:34
@@ -64,5 +66,22 @@ static LogLevel GetLogLevel(LogEvent logEvent)
return LogLevel.Info;
}
}

static LogEventLevel GetSerilogLevel(LogEvent logEvent)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I feel like this should exist somewhere already, and we should just use that. But I can't find anywhere that has this 馃槕 Oh well 馃檪

{
private readonly MessageTemplateTextFormatter _formatter;

public TraceLogsForFailedTestsSink(MessageTemplateTextFormatter formatter) => _formatter = formatter != null ? formatter : throw new ArgumentNullException(nameof(formatter));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we need to guard against nulls? We tend not to do that at Octopus, and rely instead of compile time checking.

logger.Information($"Test: {TestContext.CurrentContext.Test.Name} has hash {CurrentTestHash()}");
}
TraceLoggers.AddOrUpdate(testName, traceFileLogger, (_, _) => throw new Exception("This should never be updated. If it is, it means that a test is being run multiple times in a single test run"));
logger.Information($"Test: {TestContext.CurrentContext.Test.Name} has hash {testHash}");
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Before, we would log this always (on team city). Can we get into a situation where traceFileLogger is null and we want to log this?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmmmm, yes actually - we won't log this line anymore if:

  • Test fixture doesn't derive from BaseTest
  • SerilogLoggerBuilder is called manually to log some lines, but without initializing a trace logger.

This means it might be hard to find non-BastTest tests in the TC build log, as there is no hash printed in the test's logs.

The motivation for moving this line into this if block was that we only want this line printed once per test, but it would get printed multiples times if we print it everytime Build is called.

I'll look into some other options to deal with this scenario.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm going to re-add the HasLoggedTestHash concurrent list, as this is the reason it existed - I was trying to consolidate it with the dictionary of trace loggers, but it serves it's own purpose so we need both. 馃し馃徎

Copy link
Contributor

@sburmanoctopus sburmanoctopus left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice one.

Some nits, and a question on a better way to find the artifact directory, but it should be fine.

@acodrington acodrington merged commit 3bd003b into main Oct 18, 2023
17 checks passed
@acodrington acodrington deleted the sast/trace-logs-for-failed-tests branch October 18, 2023 08:58
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants