Suppress logs for test cases unless a failure is reported #8694

hubertp · 2024-01-05T16:08:22Z

Pull Request Description

The change adds a convenient trait ReportLogsOnFailure that, when merged with the test class, will keep logs in memory and only delegate to the underlying appender on failure. For now we only support forwarding to the console which is sufficient.
A corresponding entry in application-test.conf has to point to the new memory appender. The additional complexity in the implementation ensures that if someone forgets to mixin ReportLogsOnFailure logs appear as before i.e. they respect the log level.

As a bonus fixed arguments passed to ScalaTest in build.sbt so that we are now, again, showing timings of individual tests.

Closes #8603.

Important Notes

Before:

[info] VcsManagerTest:
[info] Initializing project
[ERROR] [2024-01-04 17:27:03,366] [org.enso.languageserver.search.SuggestionsHandler] Cannot read the package definition from [/tmp/3607843843826594318].
[info] - must create a repository (3 seconds, 538 milliseconds)
[info] - must fail to create a repository for an already existing project (141 milliseconds)
[info] Save project
[ERROR] [2024-01-04 17:27:08,346] [org.enso.languageserver.search.SuggestionsHandler] Cannot read the package definition from [/tmp/3607843843826594318].
[info] - must create a commit with a timestamp (198 milliseconds)
[ERROR] [2024-01-04 17:27:08,570] [org.enso.languageserver.search.SuggestionsHandler] Cannot read the package definition from [/tmp/3607843843826594318].
[info] - must create a commit with a name (148 milliseconds)
[ERROR] [2024-01-04 17:27:08,741] [org.enso.languageserver.search.SuggestionsHandler] Cannot read the package definition from [/tmp/3607843843826594318].
[info] - must force all pending saves (149 milliseconds)
[info] Status project
[ERROR] [2024-01-04 17:27:08,910] [org.enso.languageserver.search.SuggestionsHandler] Cannot read the package definition from [/tmp/3607843843826594318].
[info] - must report changed files since last commit (148 milliseconds)
[info] Restore project
[ERROR] [2024-01-04 17:27:09,076] [org.enso.languageserver.search.SuggestionsHandler] Cannot read the package definition from [/tmp/3607843843826594318].
[info] - must reset to the last state with committed changes (236 milliseconds)
[ERROR] [2024-01-04 17:27:09,328] [org.enso.languageserver.search.SuggestionsHandler] Cannot read the package definition from [/tmp/3607843843826594318].
[info] - must reset to a named save (pending)
[ERROR] [2024-01-04 17:27:09,520] [org.enso.languageserver.search.SuggestionsHandler] Cannot read the package definition from [/tmp/3607843843826594318].
[info] - must reset to a named save and notify about removed files *** FAILED *** (185 milliseconds)
[info]   Right({
[info]     "jsonrpc" : "2.0",
[info]     "method" : "file/event",
[info]     "params" : {
[info]       "path" : {
[info]         "rootId" : "cd84a4a3-fa50-4ead-8d80-04f6d0d124a3",
[info]         "segments" : [
[info]           "src",
[info]           "Bar.enso"
[info]         ]
[info]       },
[info]       "kind" : "Removed"
[info]     }
[info]   }) did not equal Right({
[info]     "jsonrpc" : "1.0",
[info]     "method" : "file/event",
[info]     "params" : {
[info]       "path" : {
[info]         "rootId" : "cd84a4a3-fa50-4ead-8d80-04f6d0d124a3",
[info]         "segments" : [
[info]           "src",
[info]           "Bar.enso"
[info]         ]
[info]       },
[info]       "kind" : "Removed"
[info]     }
[info]   }) (VcsManagerTest.scala:1343)
[info]   Analysis:
[info]   Right(value: Json$JObject(value: object[jsonrpc -> "2.0",method -> "file/event",params -> {
[info]   "path" : {
[info]     "rootId" : "cd84a4a3-fa50-4ead-8d80-04f6d0d124a3",
[info]     "segments" : [
[info]       "src",
[info]       "Bar.enso"
[info]     ]
[info]   },
[info]   "kind" : "Removed"
[info] }] -> object[jsonrpc -> "1.0",method -> "file/event",params -> {
[info]   "path" : {
[info]     "rootId" : "cd84a4a3-fa50-4ead-8d80-04f6d0d124a3",
[info]     "segments" : [
[info]       "src",
[info]       "Bar.enso"
[info]     ]
[info]   },
[info]   "kind" : "Removed"
[info] }]))
[ERROR] [2024-01-04 17:27:09,734] [org.enso.languageserver.search.SuggestionsHandler] Cannot read the package definition from [/tmp/3607843843826594318].
[info] List project saves
[info] - must return all explicit commits (146 milliseconds)
[info] Run completed in 9 seconds, 270 milliseconds.
[info] Total number of tests run: 9
[info] Suites: completed 1, aborted 0
[info] Tests: succeeded 8, failed 1, canceled 0, ignored 0, pending 1
[info] *** 1 TEST FAILED ***

After:

[info] VcsManagerTest:
[info] Initializing project
[info] - must create a repository (3 seconds, 554 milliseconds)
[info] - must fail to create a repository for an already existing project (164 milliseconds)
[info] Save project
[info] - must create a commit with a timestamp (212 milliseconds)
[info] - must create a commit with a name (142 milliseconds)
[info] - must force all pending saves (185 milliseconds)
[info] Status project
[info] - must report changed files since last commit (142 milliseconds)
[info] Restore project
[info] - must reset to the last state with committed changes (202 milliseconds)
[info] - must reset to a named save (pending)
[ERROR] [2024-01-04 17:24:55,738] [org.enso.languageserver.search.SuggestionsHandler] Cannot read the package definition from [/tmp/8456553964637757156].
[info] - must reset to a named save and notify about removed files *** FAILED *** (186 milliseconds)
[info]   Right({
[info]     "jsonrpc" : "2.0",
[info]     "method" : "file/event",
[info]     "params" : {
[info]       "path" : {
[info]         "rootId" : "965ed5c8-1760-4284-91f2-1376406fde0d",
[info]         "segments" : [
[info]           "src",
[info]           "Bar.enso"
[info]         ]
[info]       },
[info]       "kind" : "Removed"
[info]     }
[info]   }) did not equal Right({
[info]     "jsonrpc" : "1.0",
[info]     "method" : "file/event",
[info]     "params" : {
[info]       "path" : {
[info]         "rootId" : "965ed5c8-1760-4284-91f2-1376406fde0d",
[info]         "segments" : [
[info]           "src",
[info]           "Bar.enso"
[info]         ]
[info]       },
[info]       "kind" : "Removed"
[info]     }
[info]   }) (VcsManagerTest.scala:1343)
[info]   Analysis:
[info]   Right(value: Json$JObject(value: object[jsonrpc -> "2.0",method -> "file/event",params -> {
[info]   "path" : {
[info]     "rootId" : "965ed5c8-1760-4284-91f2-1376406fde0d",
[info]     "segments" : [
[info]       "src",
[info]       "Bar.enso"
[info]     ]
[info]   },
[info]   "kind" : "Removed"
[info] }] -> object[jsonrpc -> "1.0",method -> "file/event",params -> {
[info]   "path" : {
[info]     "rootId" : "965ed5c8-1760-4284-91f2-1376406fde0d",
[info]     "segments" : [
[info]       "src",
[info]       "Bar.enso"
[info]     ]
[info]   },
[info]   "kind" : "Removed"
[info] }]))
[info] List project saves
[info] - must return all explicit commits (131 milliseconds)
[info] Run completed in 9 seconds, 400 milliseconds.
[info] Total number of tests run: 9
[info] Suites: completed 1, aborted 0
[info] Tests: succeeded 8, failed 1, canceled 0, ignored 0, pending 1
[info] *** 1 TEST FAILED ***

Checklist

Please ensure that the following checklist has been satisfied before submitting the PR:

Screenshots/screencasts have been attached, if there are any visual changes. For interactive or animated visual changes, a screencast is preferred.
All code follows the
Scala,
Java,
and
Rust
style guides. In case you are using a language not listed above, follow the Rust style guide.
All code has been tested:
- Unit tests have been written where possible.

hubertp · 2024-01-05T16:09:01Z

build.sbt

@@ -1557,9 +1558,6 @@ lazy val runtime = (project in file("engine/runtime"))
    },
    Test / parallelExecution := false,
    Test / logBuffered := false,
-    Test / testOptions += Tests.Argument(


This has stopped working ever since we provided a global test option for ScalaTest

hubertp · 2024-01-05T16:09:49Z

engine/language-server/src/test/resources/application-test.conf

    {
      name = "console"
-      pattern = "[%level] [%d{yyyy-MM-ddTHH:mm:ssXXX}] [%logger] %msg%n%nopex"
+      pattern = "[%level] [%d{yyyy-MM-ddTHH:mm:ssXXX}] [%logger] %msg%n"


This change ensures that we print stacktraces. Since now we only do that on failure this is much more useful.

JaroslavTulach

If the logging works as described in description, then it is a huge step forward.

JaroslavTulach · 2024-01-06T14:38:40Z

engine/language-server/src/test/scala/org/enso/languageserver/vcsmanager/GitSpec.scala

@@ -19,7 +20,8 @@ class GitSpec
    extends AnyWordSpecLike
    with Matchers
    with Effects
-    with FlakySpec {
+    with FlakySpec
+    with ReportLogsOnFailure {


Using mixin is nice solution.

Akirathan

I can still see some unnecessary error logs in the job output:

Would it be possible to also get rid of those, please? Other than that, the job output got much more readable. Thanks for such a quick fix.

hubertp · 2024-01-08T13:46:21Z

Would it be possible to also get rid of those, please? Other than that, the job output got much more readable. Thanks for such a quick fix.

Yes, I haven't added the mixin in all the places yet.

The change adds a convenient trait `ReportLogsOnFailure` that, when merged with the test class, will keep logs in memory and only delegate to the underlying appender on failure. For now we only support forwarding to the console which is sufficient. As a bonus fixed arguments passed to ScalaTest in build.sbt so that we are now, again, showing timings of individual tests.

hubertp added the CI: No changelog needed Do not require a changelog entry for this PR. label Jan 5, 2024

hubertp requested review from 4e6, JaroslavTulach and Akirathan as code owners January 5, 2024 16:08

hubertp commented Jan 5, 2024

View reviewed changes

JaroslavTulach approved these changes Jan 6, 2024

View reviewed changes

enso-bot bot mentioned this pull request Jan 8, 2024

Avoid Enso/Python & co. interop problems by using Truffle TCK tests #5238

Closed

Akirathan approved these changes Jan 8, 2024

View reviewed changes

hubertp added 2 commits January 8, 2024 16:24

configure more tests

5ac856f

hubertp force-pushed the wip/hubert/8603-suppress-logs-in-tests branch from d62b561 to 5ac856f Compare January 8, 2024 15:24

hubertp added the CI: Ready to merge This PR is eligible for automatic merge label Jan 9, 2024

mergify bot merged commit 31a0dce into develop Jan 9, 2024
31 of 34 checks passed

mergify bot deleted the wip/hubert/8603-suppress-logs-in-tests branch January 9, 2024 09:59

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Suppress logs for test cases unless a failure is reported #8694

Suppress logs for test cases unless a failure is reported #8694

hubertp commented Jan 5, 2024

hubertp Jan 5, 2024

hubertp Jan 5, 2024

JaroslavTulach left a comment

JaroslavTulach Jan 6, 2024

Akirathan left a comment

hubertp commented Jan 8, 2024

Suppress logs for test cases unless a failure is reported #8694

Suppress logs for test cases unless a failure is reported #8694

Conversation

hubertp commented Jan 5, 2024

Pull Request Description

Important Notes

Checklist

hubertp Jan 5, 2024

Choose a reason for hiding this comment

hubertp Jan 5, 2024

Choose a reason for hiding this comment

JaroslavTulach left a comment

Choose a reason for hiding this comment

JaroslavTulach Jan 6, 2024

Choose a reason for hiding this comment

Akirathan left a comment

Choose a reason for hiding this comment

hubertp commented Jan 8, 2024