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 ***
```
Make sure that the correct test logging provider is loaded in `project-manager/Test`, so that only WARN and ERROR log messages are displayed. Also, make sure that the test log provider parses the correct configuration file - Rename all the `application.conf` files in the test resources to `application-test.conf`.
The problem was introduced in #8467
Add a local clone of javaFormatter plugin. The upstream is not maintained anymore. And we need to update it to use the newest Google java formatter because the old one, that we use, cannot format sources with Java 8+ syntax.
# Important Notes
Update to Google java formatter 1.18.1 - https://github.com/google/google-java-format/releases/tag/v1.18.1
Fixes a random crash (*) during instrumentation. Notice how `onTailCallReturn` calls `onReturnValue` with `null` frame.
Bonus: noticed that for some reason we weren't getting logs for `ExecutionService`. This turned out to be the problem with the logger name which by default was `[enso]` not
`[enso.org.enso.interpreter.service.ExecutionService`] and there is some logic there that normalizes the name and assumed a dot after `enso`. This change fixes the logic.
(*)
```
[enso.org.enso.interpreter.service.ExecutionService] Execution of function main failed (Cannot invoke "com.oracle.truffle.api.frame.VirtualFrame.materialize()" because "frame" is null).
java.lang.NullPointerException: Cannot invoke "com.oracle.truffle.api.frame.VirtualFrame.materialize()" because "frame" is null
at org.enso.interpreter.instrument.IdExecutionInstrument$IdEventNodeFactory$IdExecutionEventNode.onReturnValue(IdExecutionInstrument.java:246)
at org.enso.interpreter.instrument.IdExecutionInstrument$IdEventNodeFactory$IdExecutionEventNode.onTailCallReturn(IdExecutionInstrument.java:274)
at org.enso.interpreter.instrument.IdExecutionInstrument$IdEventNodeFactory$IdExecutionEventNode.onReturnExceptional(IdExecutionInstrument.java:258)
at org.graalvm.truffle/com.oracle.truffle.api.instrumentation.ProbeNode$EventProviderChainNode.innerOnReturnExceptional(ProbeNode.java:1395)
at org.graalvm.truffle/com.oracle.truffle.api.instrumentation.ProbeNode$EventChainNode.onReturnExceptional(ProbeNode.java:1031)
at org.graalvm.truffle/com.oracle.truffle.api.instrumentation.ProbeNode.onReturnExceptionalOrUnwind(ProbeNode.java:296)
at org.enso.interpreter.node.ExpressionNodeWrapper.executeGeneric(ExpressionNodeWrapper.java:119)
at org.enso.interpreter.node.ClosureRootNode.execute(ClosureRootNode.java:85)
at jdk.internal.vm.compiler/org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:718)
at jdk.internal.vm.compiler/org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.profiledPERoot(OptimizedCallTarget.java:641)
at jdk.internal.vm.compiler/org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.callBoundary(OptimizedCallTarget.java:574)
at jdk.internal.vm.compiler/org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.doInvoke(OptimizedCallTarget.java:558)
at jdk.internal.vm.compiler/org.graalvm.compiler.truffle.runtime.OptimizedCallTarget.callDirect(OptimizedCallTarget.java:504)
at jdk.internal.vm.compiler/org.graalvm.compiler.truffle.runtime.OptimizedDirectCallNode.call(OptimizedDirectCallNode.java:69)
at org.enso.interpreter.node.callable.thunk.ThunkExecutorNode.doCached(ThunkExecutorNode.java:69)
at org.enso.interpreter.node.callable.thunk.ThunkExecutorNodeGen.executeAndSpecialize(ThunkExecutorNodeGen.java:207)
at org.enso.interpreter.node.callable.thunk.ThunkExecutorNodeGen.executeThunk(ThunkExecutorNodeGen.java:167)
...
```
# Important Notes
Fixes regressions introduced in #8148 and #8162
This change fixes a regression introduced in #7918, which prevented the execution from setting the right log level either via env var or parameter.
Now passing either of the options returns logs of the expected level in the log file:
- `ENSO_LOG_TO_FILE_LOG_LEVEL = trace`
- ... `-vv` ...
Fixes#8274
Previously custom log levels applied only to non-Truffle loggers. To allow it, filtering has to be applied appropriately at two places - first at Java's Handler and then essentially re-confirmed at SLF4J's logger to which the former forwards to.
Filters compose in an `AND` condition, therefore default log level check had to be merged into our custom filters.
`TruffleLogger` has a builtin functionality to perform the filtering when context is configured appropriately. This should be much more efficient than adding a `Filter` to the JUL Handler explicitly.
# Important Notes
```
JAVA_OPTS="-org.enso.compiler.SerializationManager.Logger.level=debug" ./built-distribution/enso-engine-0.0.0-dev-linux-amd64/enso-0.0.0-dev/bin/enso --run
```
will now assign a custom log level to `SerializationManager` Logger.
* Reduce extra output in compilation and tests
I couldn't stand the amount of extra output that we got when compiling
a clean project and when executing regular tests. We should strive to
keep output clean and not print anything additional to stdout/stderr.
* Getting rid of explicit setup by service loading
In order for SL4J to use service loading correctly had to upgrade to
latest slf4j. Unfortunately `TestLogProvider` which essentially
delegates to `logback` provider will lead to spurious ambiguous warnings
on multiple providers. In order to dictate which one to use and
therefore eliminate the warnings we can use the `slf4j.provider` env
var, which is only available in slf4j 2.x.
Now, there is no need to explicitly call `LoggerSetup.get().setup()` as
that is being called during service setup.
* legal review
* linter
* Ensure ConsoleHandler uses the default level
ConsoleHandler's constructor uses `Level.INFO` which is unnecessary for
tests.
* report warnings
* Enable log-to-file configuration
PR #7825 enabled parallel logging to a file with a much more
fine-grained log level by default.
However, logging at `TRACE` level on Windows appears to be still
problematic.
This PR reduced the default log level to file from `DEBUG` to `TRACE`
and allows to control it via an environment variable if one wishes to
change the verbosity without making code changes.
* PR comments
* Always log verbose to a file
The change adds an option by default to always log to a file with
verbose log level.
The implementation is a bit tricky because in the most common use-case
we have to always log in verbose mode to a socket and only later apply
the desired log levels. Previously socket appender would respect the
desired log level already before forwarding the log.
If by default we log to a file, verbose mode is simply ignored and does
not override user settings.
To test run `project-manager` with `ENSO_LOGSERVER_APPENDER=console` env
variable. That will output to the console with the default `INFO` level
and `TRACE` log level for the file.
* add docs
* changelog
* Address some PR requests
1. Log INFO level to CONSOLE by default
2. Change runner's default log level from ERROR to WARN
Took a while to figure out why the correct log level wasn't being passed
to the language server, therefore ignoring the (desired) verbose logs
from the log file.
* linter
* 3rd party uses log4j for logging
Getting rid of the warning by adding a log4j over slf4j bridge:
```
ERROR StatusLogger Log4j2 could not find a logging implementation. Please add log4j-core to the classpath. Using SimpleLogger to log to the console...
```
* legal review update
* Make sure tests use test resources
Having `application.conf` in `src/main/resources` and `test/resources`
does not guarantee that in Tests we will pick up the latter. Instead, by
default it seems to do some kind of merge of different configurations,
which is far from desired.
* Ensure native launcher test log to console only
Logging to console and (temporary) files is problematic for Windows.
The CI also revealed a problem with the native configuration because it
was not possible to modify the launcher via env variables as everything
was initialized during build time.
* Adapt to method changes
* Potentially deal with Windows failures
This change replaces Enso's custom logger with an existing, mostly off the shelf logging implementation. The change attempts to provide a 1:1 replacement for the existing solution while requiring only a minimal logic for the initialization.
Loggers are configured completely via `logging-server` section in `application.conf` HOCON file, all initial logback configuration has been removed. This opens up a lot of interesting opportunities because we can benefit from all the well maintained slf4j implementations without being to them in terms of functionality.
Most important differences have been outlined in `docs/infrastructure/logging.md`.
# Important Notes
Addresses:
- #7253
- #6739
