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’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

testing: Improve logging from TestAgent #7546

Merged
merged 4 commits into from
Mar 31, 2020
Merged

Conversation

dnephin
Copy link
Contributor

@dnephin dnephin commented Mar 30, 2020

I find the log output in tests somewhat difficult to work with.

As an example, here is a log line before this change:

TestPreparedQuery_Execute/#07: writer.go:29: 2020-03-30T11:31:56.040-0400 [INFO]  TestPreparedQuery_Execute/#07: started state syncer

There are 112 characters before the relevant log line text starts. The name is duplicated, and is unnecessary because go test already aggregates the output by test. The full date/time is most likely not relevant, either CI will give us the time, or for a local run we know the time. The time is really only relevant to understand the elapsed time between log lines. writer.go:29 is the same on every log line.

After this change:

14:06.240 [INFO]  TestAgent: started state syncer

The time is still there, so we can see elapsed time between statements. For the few tests which run multiple agents TestAgent will be replaced with the name provided by the test, so we can tell which agent produced the log message.

Previously the log output included the test name twice and a long date
format. The test output is already grouped by test, so adding the test
name did not add any new information. The date and time are only useful
to understand elapsed time, so using a short format should provide
succident detail.

Also fixed a bug in NewTestAgentWithFields where nil was returned
instead of the test agent.
@dnephin dnephin added the theme/internal-cleanup Used to identify tech debt, testing improvements, code refactoring, and non-impactful optimization label Mar 30, 2020
// default value. Tests which set a custom name for multiple agents will
// use the provided name.
// TODO: remove TestAgent.Name and accept a name arg on Start, to remove
// this workaround.
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 can make this change after the PR merges. It should be easy to automate, but will change ~800 lines. I did not want all of those changes distracting from the logging changes in this PR.

agent/testagent.go Outdated Show resolved Hide resolved
And re-add the name to the logger so that log messages from different agents
in a single can be identified.
Copy link
Member

@mkeeler mkeeler left a comment

Choose a reason for hiding this comment

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

:shipit:

@dnephin dnephin merged commit fd7383e into master Mar 31, 2020
@dnephin dnephin deleted the dnephin/logging-in-tests branch March 31, 2020 15:08
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
theme/internal-cleanup Used to identify tech debt, testing improvements, code refactoring, and non-impactful optimization
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants