Restore behaviour of not having test logs on stdout/stderr by default

[belimawr]

With the refactoring to use global loggers, logp has changed behaviour and now tests that use a testing logger, like logptest.NewTestingLogger. Making the output of go test -v pretty much unreadable, it is not possible to see the tests that are running and the time they took.

As an example, let's get Filebeat Filestream's tests, from Beats root:

cd filebeat/input/filestream
git checkout v9.0.0
go test -v -count=1

The output is a clear list of all the tests run and the time they took. It's 208 lines long.

output

% go test -v -count=1
=== RUN   TestConfigValidate
=== RUN   TestConfigValidate/paths_cannot_be_empty
--- PASS: TestConfigValidate (0.00s)
    --- PASS: TestConfigValidate/paths_cannot_be_empty (0.00s)
=== RUN   TestValidateInputIDs
=== RUN   TestValidateInputIDs/empty_config
=== RUN   TestValidateInputIDs/one_empty_ID_is_allowed
=== RUN   TestValidateInputIDs/duplicated_empty_ID
=== RUN   TestValidateInputIDs/duplicated_IDs
=== RUN   TestValidateInputIDs/duplicated_IDs_and_empty_ID
=== RUN   TestValidateInputIDs/only_unique_IDs
--- PASS: TestValidateInputIDs (0.00s)
    --- PASS: TestValidateInputIDs/empty_config (0.00s)
    --- PASS: TestValidateInputIDs/one_empty_ID_is_allowed (0.00s)
    --- PASS: TestValidateInputIDs/duplicated_empty_ID (0.00s)
    --- PASS: TestValidateInputIDs/duplicated_IDs (0.00s)
    --- PASS: TestValidateInputIDs/duplicated_IDs_and_empty_ID (0.00s)
    --- PASS: TestValidateInputIDs/only_unique_IDs (0.00s)
=== RUN   TestCopyTruncateProspector_Create
=== RUN   TestCopyTruncateProspector_Create/first_rotated_file,_when_rotated_file_not_exist
=== RUN   TestCopyTruncateProspector_Create/one_new_file,_then_rotated
=== RUN   TestCopyTruncateProspector_Create/one_new_file,_then_rotated_twice_in_order
=== RUN   TestCopyTruncateProspector_Create/one_new_file,_then_rotated_twice_with_renaming
--- PASS: TestCopyTruncateProspector_Create (0.00s)
    --- PASS: TestCopyTruncateProspector_Create/first_rotated_file,_when_rotated_file_not_exist (0.00s)
    --- PASS: TestCopyTruncateProspector_Create/one_new_file,_then_rotated (0.00s)
    --- PASS: TestCopyTruncateProspector_Create/one_new_file,_then_rotated_twice_in_order (0.00s)
    --- PASS: TestCopyTruncateProspector_Create/one_new_file,_then_rotated_twice_with_renaming (0.00s)
=== RUN   TestNumericSorter
=== RUN   TestNumericSorter/one_fileinfo
=== RUN   TestNumericSorter/ordered_fileinfos
=== RUN   TestNumericSorter/unordered_fileinfos
=== RUN   TestNumericSorter/unordered_fileinfos_with_numbers_in_filename
--- PASS: TestNumericSorter (0.00s)
    --- PASS: TestNumericSorter/one_fileinfo (0.00s)
    --- PASS: TestNumericSorter/ordered_fileinfos (0.00s)
    --- PASS: TestNumericSorter/unordered_fileinfos (0.00s)
    --- PASS: TestNumericSorter/unordered_fileinfos_with_numbers_in_filename (0.00s)
=== RUN   TestDateSorter
=== RUN   TestDateSorter/one_fileinfo
=== RUN   TestDateSorter/ordered_fileinfos
=== RUN   TestDateSorter/unordered_fileinfos
--- PASS: TestDateSorter (0.00s)
    --- PASS: TestDateSorter/one_fileinfo (0.00s)
    --- PASS: TestDateSorter/ordered_fileinfos (0.00s)
    --- PASS: TestDateSorter/unordered_fileinfos (0.00s)
=== RUN   TestLogFileTimedClosing
=== RUN   TestLogFileTimedClosing/read_from_file_and_close_on_EOF
=== RUN   TestLogFileTimedClosing/read_from_file_and_close_inactive
=== RUN   TestLogFileTimedClosing/read_from_file_and_close_after_interval
--- PASS: TestLogFileTimedClosing (5.04s)
    --- PASS: TestLogFileTimedClosing/read_from_file_and_close_on_EOF (0.00s)
    --- PASS: TestLogFileTimedClosing/read_from_file_and_close_inactive (2.00s)
    --- PASS: TestLogFileTimedClosing/read_from_file_and_close_after_interval (3.04s)
=== RUN   TestLogFileTruncated
--- PASS: TestLogFileTruncated (0.00s)
=== RUN   TestFileWatcher
=== RUN   TestFileWatcher/detects_a_new_file
=== RUN   TestFileWatcher/detects_a_file_write
=== RUN   TestFileWatcher/detects_a_file_rename
=== RUN   TestFileWatcher/detects_a_file_truncate
=== RUN   TestFileWatcher/emits_truncate_on_touch_when_resend_on_touch_is_enabled
=== RUN   TestFileWatcher/detects_a_file_remove
=== RUN   TestFileWatcher/propagates_a_fingerprints_for_a_new_file
=== RUN   TestFileWatcher/does_not_emit_events_if_a_file_is_touched_and_resend_on_touch_is_disabled
=== RUN   TestFileWatcher/does_not_emit_events_for_empty_files
=== RUN   TestFileWatcher/does_not_emit_events_for_empty_files/issues_a_debug_message_in_logs
=== RUN   TestFileWatcher/does_not_emit_events_for_empty_files/emits_a_create_event_once_something_is_written_to_the_empty_file
=== RUN   TestFileWatcher/does_not_emit_an_event_for_a_fingerprint_collision
=== RUN   TestFileWatcher/does_not_log_warnings_on_duplicate_globs_and_filters_out_duplicates
--- PASS: TestFileWatcher (1.65s)
    --- PASS: TestFileWatcher/detects_a_new_file (0.00s)
    --- PASS: TestFileWatcher/detects_a_file_write (0.10s)
    --- PASS: TestFileWatcher/detects_a_file_rename (0.10s)
    --- PASS: TestFileWatcher/detects_a_file_truncate (0.10s)
    --- PASS: TestFileWatcher/emits_truncate_on_touch_when_resend_on_touch_is_enabled (0.10s)
    --- PASS: TestFileWatcher/detects_a_file_remove (0.10s)
    --- PASS: TestFileWatcher/propagates_a_fingerprints_for_a_new_file (0.00s)
    --- PASS: TestFileWatcher/does_not_emit_events_if_a_file_is_touched_and_resend_on_touch_is_disabled (1.00s)
    --- PASS: TestFileWatcher/does_not_emit_events_for_empty_files (0.05s)
        --- PASS: TestFileWatcher/does_not_emit_events_for_empty_files/issues_a_debug_message_in_logs (0.01s)
        --- PASS: TestFileWatcher/does_not_emit_events_for_empty_files/emits_a_create_event_once_something_is_written_to_the_empty_file (0.04s)
    --- PASS: TestFileWatcher/does_not_emit_an_event_for_a_fingerprint_collision (0.10s)
    --- PASS: TestFileWatcher/does_not_log_warnings_on_duplicate_globs_and_filters_out_duplicates (0.00s)
=== RUN   TestFileScanner
=== RUN   TestFileScanner/returns_all_files_when_no_limits,_not_including_the_repeated_symlink
=== RUN   TestFileScanner/returns_filtered_files,_excluding_symlinks
=== RUN   TestFileScanner/returns_files_according_to_excluded_list
=== RUN   TestFileScanner/returns_no_symlink_if_the_original_file_is_excluded
=== RUN   TestFileScanner/returns_files_according_to_included_list
=== RUN   TestFileScanner/returns_no_included_symlink_if_the_original_file_is_not_included
=== RUN   TestFileScanner/returns_an_included_symlink_if_the_original_file_is_included
=== RUN   TestFileScanner/returns_all_files_except_too_small_to_fingerprint
=== RUN   TestFileScanner/returns_all_files_that_match_a_non-standard_fingerprint_window
=== RUN   TestFileScanner/does_not_issue_warnings_when_file_is_too_small
=== RUN   TestFileScanner/returns_error_when_creating_scanner_with_a_fingerprint_too_small
--- PASS: TestFileScanner (0.00s)
    --- PASS: TestFileScanner/returns_all_files_when_no_limits,_not_including_the_repeated_symlink (0.00s)
    --- PASS: TestFileScanner/returns_filtered_files,_excluding_symlinks (0.00s)
    --- PASS: TestFileScanner/returns_files_according_to_excluded_list (0.00s)
    --- PASS: TestFileScanner/returns_no_symlink_if_the_original_file_is_excluded (0.00s)
    --- PASS: TestFileScanner/returns_files_according_to_included_list (0.00s)
    --- PASS: TestFileScanner/returns_no_included_symlink_if_the_original_file_is_not_included (0.00s)
    --- PASS: TestFileScanner/returns_an_included_symlink_if_the_original_file_is_included (0.00s)
    --- PASS: TestFileScanner/returns_all_files_except_too_small_to_fingerprint (0.00s)
    --- PASS: TestFileScanner/returns_all_files_that_match_a_non-standard_fingerprint_window (0.00s)
    --- PASS: TestFileScanner/does_not_issue_warnings_when_file_is_too_small (0.00s)
    --- PASS: TestFileScanner/returns_error_when_creating_scanner_with_a_fingerprint_too_small (0.00s)
=== RUN   TestFileIdentifier
=== RUN   TestFileIdentifier/native_file_identifier
=== RUN   TestFileIdentifier/native_file_identifier_with_suffix
=== RUN   TestFileIdentifier/path_identifier
=== RUN   TestFileIdentifier/fingerprint_identifier
--- PASS: TestFileIdentifier (0.00s)
    --- PASS: TestFileIdentifier/native_file_identifier (0.00s)
    --- PASS: TestFileIdentifier/native_file_identifier_with_suffix (0.00s)
    --- PASS: TestFileIdentifier/path_identifier (0.00s)
    --- PASS: TestFileIdentifier/fingerprint_identifier (0.00s)
=== RUN   TestTakeOverTags
=== RUN   TestTakeOverTags/test-take_over-true
=== RUN   TestTakeOverTags/test-take_over-false
--- PASS: TestTakeOverTags (0.00s)
    --- PASS: TestTakeOverTags/test-take_over-true (0.00s)
    --- PASS: TestTakeOverTags/test-take_over-false (0.00s)
=== RUN   TestCreateProspector
=== RUN   TestCreateProspector/SetIgnoreInactiveSince
=== RUN   TestCreateProspector/SetIgnoreInactiveSince/ignore_inactive_since_set_to_since_last_start
=== RUN   TestCreateProspector/SetIgnoreInactiveSince/ignore_inactive_since_set_to_since_first_start
=== RUN   TestCreateProspector/SetIgnoreInactiveSince/ignore_inactive_since_not_set
=== RUN   TestCreateProspector/file_watcher_and_file_identity_compatibility
=== RUN   TestCreateProspector/file_watcher_and_file_identity_compatibility/returns_no_error_for_a_fully_default_config
=== RUN   TestCreateProspector/file_watcher_and_file_identity_compatibility/returns_no_error_when_fingerprint_and_identity_is_configured
=== RUN   TestCreateProspector/file_watcher_and_file_identity_compatibility/returns_no_error_when_fingerprint_and_other_identity_is_configured
=== RUN   TestCreateProspector/file_watcher_and_file_identity_compatibility/returns_error_when_fingerprint_is_disabled_but_fingerprint_identity_is_configured
--- PASS: TestCreateProspector (0.00s)
    --- PASS: TestCreateProspector/SetIgnoreInactiveSince (0.00s)
        --- PASS: TestCreateProspector/SetIgnoreInactiveSince/ignore_inactive_since_set_to_since_last_start (0.00s)
        --- PASS: TestCreateProspector/SetIgnoreInactiveSince/ignore_inactive_since_set_to_since_first_start (0.00s)
        --- PASS: TestCreateProspector/SetIgnoreInactiveSince/ignore_inactive_since_not_set (0.00s)
    --- PASS: TestCreateProspector/file_watcher_and_file_identity_compatibility (0.00s)
        --- PASS: TestCreateProspector/file_watcher_and_file_identity_compatibility/returns_no_error_for_a_fully_default_config (0.00s)
        --- PASS: TestCreateProspector/file_watcher_and_file_identity_compatibility/returns_no_error_when_fingerprint_and_identity_is_configured (0.00s)
        --- PASS: TestCreateProspector/file_watcher_and_file_identity_compatibility/returns_no_error_when_fingerprint_and_other_identity_is_configured (0.00s)
        --- PASS: TestCreateProspector/file_watcher_and_file_identity_compatibility/returns_error_when_fingerprint_is_disabled_but_fingerprint_identity_is_configured (0.00s)
=== RUN   TestProspector_InitCleanIfRemoved
=== RUN   TestProspector_InitCleanIfRemoved/prospector_init_with_clean_removed_enabled_with_no_entries
=== RUN   TestProspector_InitCleanIfRemoved/prospector_init_with_clean_removed_disabled_with_entries
=== RUN   TestProspector_InitCleanIfRemoved/prospector_init_with_clean_removed_enabled_with_entries
--- PASS: TestProspector_InitCleanIfRemoved (0.00s)
    --- PASS: TestProspector_InitCleanIfRemoved/prospector_init_with_clean_removed_enabled_with_no_entries (0.00s)
    --- PASS: TestProspector_InitCleanIfRemoved/prospector_init_with_clean_removed_disabled_with_entries (0.00s)
    --- PASS: TestProspector_InitCleanIfRemoved/prospector_init_with_clean_removed_enabled_with_entries (0.00s)
=== RUN   TestProspector_InitUpdateIdentifiers
=== RUN   TestProspector_InitUpdateIdentifiers/prospector_init_does_not_update_keys_if_there_are_no_entries
=== RUN   TestProspector_InitUpdateIdentifiers/prospector_init_does_not_update_keys_of_not_existing_files
=== RUN   TestProspector_InitUpdateIdentifiers/prospector_init_does_not_update_keys_if_new_file_identity_is_not_fingerprint
--- PASS: TestProspector_InitUpdateIdentifiers (0.00s)
    --- PASS: TestProspector_InitUpdateIdentifiers/prospector_init_does_not_update_keys_if_there_are_no_entries (0.00s)
    --- PASS: TestProspector_InitUpdateIdentifiers/prospector_init_does_not_update_keys_of_not_existing_files (0.00s)
    --- PASS: TestProspector_InitUpdateIdentifiers/prospector_init_does_not_update_keys_if_new_file_identity_is_not_fingerprint (0.00s)
=== RUN   TestMigrateRegistryToFingerprint
=== RUN   TestMigrateRegistryToFingerprint/fingerprint_to_native_fails
=== RUN   TestMigrateRegistryToFingerprint/path_to_native_fails
=== RUN   TestMigrateRegistryToFingerprint/inode_to_fingerprint_succeeds
=== RUN   TestMigrateRegistryToFingerprint/path_to_fingerprint_succeeds
=== RUN   TestMigrateRegistryToFingerprint/fingerprint_to_fingerprint_fails
--- PASS: TestMigrateRegistryToFingerprint (0.00s)
    --- PASS: TestMigrateRegistryToFingerprint/fingerprint_to_native_fails (0.00s)
    --- PASS: TestMigrateRegistryToFingerprint/path_to_native_fails (0.00s)
    --- PASS: TestMigrateRegistryToFingerprint/inode_to_fingerprint_succeeds (0.00s)
    --- PASS: TestMigrateRegistryToFingerprint/path_to_fingerprint_succeeds (0.00s)
    --- PASS: TestMigrateRegistryToFingerprint/fingerprint_to_fingerprint_fails (0.00s)
=== RUN   TestProspectorNewAndUpdatedFiles
=== RUN   TestProspectorNewAndUpdatedFiles/two_new_files
=== RUN   TestProspectorNewAndUpdatedFiles/one_updated_file
=== RUN   TestProspectorNewAndUpdatedFiles/one_updated_then_truncated_file
=== RUN   TestProspectorNewAndUpdatedFiles/old_files_with_ignore_older_configured
=== RUN   TestProspectorNewAndUpdatedFiles/newer_files_with_ignore_older
--- PASS: TestProspectorNewAndUpdatedFiles (0.00s)
    --- PASS: TestProspectorNewAndUpdatedFiles/two_new_files (0.00s)
    --- PASS: TestProspectorNewAndUpdatedFiles/one_updated_file (0.00s)
    --- PASS: TestProspectorNewAndUpdatedFiles/one_updated_then_truncated_file (0.00s)
    --- PASS: TestProspectorNewAndUpdatedFiles/old_files_with_ignore_older_configured (0.00s)
    --- PASS: TestProspectorNewAndUpdatedFiles/newer_files_with_ignore_older (0.00s)
=== RUN   TestProspectorHarvesterUpdateIgnoredFiles
--- PASS: TestProspectorHarvesterUpdateIgnoredFiles (0.02s)
=== RUN   TestProspectorDeletedFile
=== RUN   TestProspectorDeletedFile/one_deleted_file_without_clean_removed
=== RUN   TestProspectorDeletedFile/one_deleted_file_with_clean_removed
--- PASS: TestProspectorDeletedFile (0.00s)
    --- PASS: TestProspectorDeletedFile/one_deleted_file_without_clean_removed (0.00s)
    --- PASS: TestProspectorDeletedFile/one_deleted_file_with_clean_removed (0.00s)
=== RUN   TestProspectorRenamedFile
=== RUN   TestProspectorRenamedFile/one_renamed_file_without_rename_tracker
=== RUN   TestProspectorRenamedFile/one_renamed_file_with_rename_tracker
=== RUN   TestProspectorRenamedFile/one_renamed_file_with_rename_tracker_with_close_renamed
--- PASS: TestProspectorRenamedFile (0.00s)
    --- PASS: TestProspectorRenamedFile/one_renamed_file_without_rename_tracker (0.00s)
    --- PASS: TestProspectorRenamedFile/one_renamed_file_with_rename_tracker (0.00s)
    --- PASS: TestProspectorRenamedFile/one_renamed_file_with_rename_tracker_with_close_renamed (0.00s)
=== RUN   TestOnRenameFileIdentity
=== RUN   TestOnRenameFileIdentity/identifier_name_from_meta_is_kept
=== RUN   TestOnRenameFileIdentity/identifier_from_prospector_is_used
--- PASS: TestOnRenameFileIdentity (0.00s)
    --- PASS: TestOnRenameFileIdentity/identifier_name_from_meta_is_kept (0.00s)
    --- PASS: TestOnRenameFileIdentity/identifier_from_prospector_is_used (0.00s)
PASS
ok      github.com/elastic/beats/v7/filebeat/input/filestream   6.756s

However the same thing ran on main outputs 837 119 lines, that's 125Mb.

git checkout main
go test -v -count=1

This output is just too large to be of any use and it is impossible to see which tests were run.

Another problem of the new behaviour is printing the stack trace at error level by default, this makes the output look like a panic, which can be very confusing.

Proposal

Revert to the previous behaviour (like from v0.18.9) of not having development/test loggers logging to stdout/err and do not print the stack trace at level error.

[AndersonQ]

that's definitively a problem. I started to tun the tests without -v, I've just tried and indeed the output now is useless.
Also it prints the stack trace by default on error, which, in my opinion isn't good. It looks like a panic and we have tests that expect errors in the logs.

I'd suggest also removing the stack-trace and if anyone needs it, they can add it on their own

[belimawr]

Also it prints the stack trace by default on error, which, in my opinion isn't good. It looks like a panic and we have tests that expect errors in the logs.

+1 for that.

My current "workaround" is to use logp.NewNopLogger I created to circumvent this problem.

[belimawr]

Also it prints the stack trace by default on error, which, in my opinion isn't good. It looks like a panic and we have tests that expect errors in the logs.

+1 for that.
My current "workaround" is to use logp.NewNopLogger I created to circumvent this problem.

I also added your point about the stack trace to the issue.

[cmacknz]

With the refactoring to use global loggers, logp has changed behaviour and now tests that use a testing logger, like logptest.NewTestingLogger. Making the output of go test -v pretty much unreadable, it is not possible to see the tests that are running and the time they took.

Can we double check the only change here is tests, and this is a symptom that would affect use outside of tests. Do we know why this is happening now? It doesn't sound like an entirely intentional change to me

However the same thing ran on main outputs 837 119 lines, that's 125Mb.

This is ridiculous.

Revert to the previous behaviour (like from v0.18.9) of not having development/test loggers logging to stdout/err and do not print the stack trace at level error.

The test loggers should probably log to a separate file so the log lines aren't lost. What did they do before?

[belimawr]

Can we double check the only change here is tests, and this is a symptom that would affect use outside of tests. Do we know why this is happening now?

Yes, this is restricted to tests, it comes from the refactoring to stop using global loggers, now the test loggers call zaptest.NewLogger(t) and it logs all messages to the given testing.TB.

However the same thing ran on main outputs 837 119 lines, that's 125Mb.

This is ridiculous.

This is the product of how we test Filetream and how verbose our logs can be. To test Filestream in many places we set the prospector check interval to a very low value like 10ms or even 1ms (the default is 10s). This makes the tests run very fast, but ever file system scan generates one or more log entries. This is enough to flood the logs, then we add on top of this some tests that need to wait for a period of time, while the prospector is scanning the file system, like the ones for close inactive and we have this HUGE log output.

I confess I did not expect the amount of logs to be that bad as most of the time I was running a single test, but for this issue I naively ran all tests from Filestream and was shocked by the output.

The test loggers should probably log to a separate file so the log lines aren't lost. What did they do before?
Before they were lost/not kept. I believe this is due to the fact the logging output was not correctly setup by the tests.

When they were set to be collected in-memory, they'd just stay in memory and never flood the test output.

Also before it was more common (at least for the tests I mostly interact with) to have tests call logp.DevelopmentSetup(logp.ToObserverOutput()) which never sent log entries to the output of the test.

The test loggers should probably log to a separate file so the log lines aren't lost.

I can see the value in this, but I believe the practical use is very limited.

For CI failures, we'd need to collect the files from failed tests. For debugging a failing test locally, usually I end up adding more printf-debug statements than the logs. So if I'm already changing the code I'd not mind also changing the logging configuration to write to stderr/out or a file, if I really need the logs.

At least as a first fix/implementation, I'd restore the previous behaviour of just sending the logs to the void. Then we can decide if we want to invest time on having a fancy "failed test log collection system".

[khushijain21]

logptest.NewTestingLogger was introduced to match the behavior of TestingSetup which logs if -v flag is passed or if the test fails. https://github.com/khushijain21/elastic-agent-libs/blob/eventLogging/logp/core.go#L419-L426

I have restored the behavior of filebeat/input/filestream tests in this PR now- elastic/beats#45285 - and we shouldn't see massive logs anymore

But we will still see verbose logging wherever logp.TestingSetup() is called

Another problem of the new behaviour is printing the stack trace at error level by default, this makes the output look like a panic, which can be very confusing.

Also for this, I agree this is strange. Maybe moving to logp.NewNopLogger() is a good workaround and only use logptest.NewTestingLogger when we want to debug tests

[belimawr]

Thanks a lot for fixing it for the Filestream input @khushijain21 !!

I was reviewing @khushijain21's PR and it clicked why now we're seeing so many logs in the tests. Before all the refactoring to stop using global loggers, many tests never configured any logger, many functions/methods relied on global loggers, which is disabled by default, hence producing no logs. By explicitly giving a test logger during the refactoring, they started to actually produce logs.

[cmacknz]

Thanks, now we know why this is happening and that it doesn't affect any use case outside of tests 👍

For CI failures, we'd need to collect the files from failed tests.

Just a note that if you log to a directory Buildkite was configured to pull build artifacts from this will just work with minimum effort.

[belimawr]

Just a note that if you log to a directory Buildkite was configured to pull build artifacts from this will just work with minimum effort.

BuildKite by "default" (it's our configuration) only pulls certain files, for Filebeat unit tests it is (defined here)

        artifact_paths:
          - "filebeat/build/*.xml"
          - "filebeat/build/*.json"

The Go integration tests collects all files from build/integration-tests (defined here):

        artifact_paths:
          - "filebeat/build/*.xml"
          - "filebeat/build/*.json"
          - "filebeat/build/integration-tests/*"
          - "filebeat/build/integration-tests/Test*/*"
          - "filebeat/build/integration-tests/Test*/data/**/*"

I believe this came from a concern (at least at the Jenkins time) about disk usage/storage costs of keeping too much data around. I'm not sure if this is still a concern on BuildKite.

Anyways, aside from updating the logger/test logger, we'd still need to update the BuildKite pipelines to collect the logs.