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.

Sign up for GitHub

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

Jump to bottom

Verbosity Level gets ignored on Init #9372

Closed
pepper-jk opened this issue Nov 4, 2024 · 1 comment
Closed

Verbosity Level gets ignored on Init #9372

pepper-jk opened this issue Nov 4, 2024 · 1 comment
Assignees
@sschuberth
Labels
bug Issues that are considered to be bugs docker About Docker topics

Comments

@pepper-jk
Copy link
Contributor

Describe the bug

When executing ORT with a verbosity level flag such as --warn the initial logs (before "ORT Logo") still show higher level output such as INFO.

I noticed a comment about two loggers being used, one of which does not have log level control. Could be a good place to start looking.

To Reproduce

  1. execute any ort command with --warn verbosity flag, e.g. ort --warn analyze -i /path/to/project -o /path/to/ort-results.
  2. look at logs

Expected behavior

Still prints INFO level events.

Console / log output

Again (mostly) the events during initialization seem to be effected by this.

14:11:14,725 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.5.9
14:11:14,727 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1807e3f6 - No custom configurators were discovered as a service.
14:11:14,727 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1807e3f6 - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
14:11:14,728 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1807e3f6 - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
14:11:14,732 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
14:11:14,733 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
14:11:14,741 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1807e3f6 - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 5 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
14:11:14,741 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1807e3f6 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
14:11:14,741 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1807e3f6 - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
14:11:14,742 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
14:11:14,745 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/opt/ort/lib/helper-cli-35.0.0.jar!/logback.xml]
14:11:14,746 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@480d3575 - Resource [logback.xml] occurs multiple times on the classpath.
14:11:14,746 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@480d3575 - Resource [logback.xml] occurs at [jar:file:/opt/ort/lib/cli-35.0.0.jar!/logback.xml]
14:11:14,746 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@480d3575 - Resource [logback.xml] occurs at [jar:file:/opt/ort/lib/helper-cli-35.0.0.jar!/logback.xml]
14:11:14,751 |-INFO in ConfigurationWatchList(mainURL=jar:file:/opt/ort/lib/helper-cli-35.0.0.jar!/logback.xml, fileWatchList={}, urlWatchList=[}) - URL [jar:file:/opt/ort/lib/helper-cli-35.0.0.jar!/logback.xml] is not of type file
14:11:14,862 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [STDOUT]
14:11:14,862 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
14:11:14,870 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
14:11:14,904 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to WARN
14:11:14,905 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[ROOT]
14:11:14,906 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.apache.http.headers] to ERROR
14:11:14,906 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.apache.http.wire] to ERROR
14:11:14,906 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.eclipse.jgit.internal.storage.file.FileSnapshot] to ERROR
14:11:14,906 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.ossreviewtoolkit.analyzer.managers.Yarn2] to INFO
14:11:14,906 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.ossreviewtoolkit.clients.fossid.FossIdRestService] to INFO
14:11:14,906 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.ossreviewtoolkit.plugins.reporters.fossid.FossIdReporter] to INFO
14:11:14,906 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.ossreviewtoolkit.plugins.reporters.fossid.FossIdSnippetReporter] to INFO
14:11:14,906 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.ossreviewtoolkit.scanner.scanners.fossid.FossId] to INFO
14:11:14,906 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.ossreviewtoolkit.scanner.scanners.fossid.FossIdConfig] to INFO
14:11:14,906 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [org.ossreviewtoolkit.scanner.scanners.fossid.FossIdUrlProvider] to INFO
14:11:14,906 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@5e7cd6cc - End of configuration.
14:11:14,907 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@68c9d179 - Registering current configuration as safe fallback point
14:11:14,907 |-INFO in ch.qos.logback.classic.util.ContextInitializer@1807e3f6 - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 166 milliseconds. ExecutionStatus=DO_NOT_INVOKE_NEXT_IF_ANY

Hoplite is configured to infer which sealed type to choose by inspecting the config values at runtime. This behaviour is now deprecated in favour of explicitly specifying the type through a discriminator field. In 3.0 this new behavior will become the default. To enable this behavior now (and disable this warning), invoke withExplicitSealedTypes() on the ConfigLoaderBuilder.
14:22:24.554 [main] INFO  org.ossreviewtoolkit.utils.common.EnvironmentVariableFilter - EnvironmentVariableFilter initialized with denySubstrings = [key, pass, pwd, token, user] and allowNames = [CARGO_HTTP_USER_AGENT, COMPOSER_ALLOW_SUPERUSER, CONAN_LOGIN_ENCRYPTION_KEY, CONAN_LOGIN_USERNAME, CONAN_PASSWORD, CONAN_USERNAME, CONAN_USER_HOME, CONAN_USER_HOME_SHORT, DOTNET_CLI_CONTEXT_ANSI_PASS_THRU, GIT_ASKPASS, GIT_HTTP_USER_AGENT, GRADLE_USER_HOME, HACKAGE_USERNAME, HACKAGE_PASSWORD, HACKAGE_KEY, PWD, USER, USERPROFILE].
______________________________
/        \_______   \__    ___/ The OSS Review Toolkit, version 35.0.0,
|    |   | |       _/ |    |    built with JDK 21.0.4+7-LTS, running under Java 21.0.4.
|    |   | |    |   \ |    |    Executing 'analyze' as 'ort' on Linux
\________/ |____|___/ |____|    with 4 CPUs and a maximum of 3998 MiB of memory.
 
[...]

Environment

  • ORT version: 35.0.0
  • Java version: 21.0.4
  • OS: Linux

Using a copy of the official Docker Image.

Additional context

We first noticed the behavior when changing our GitLab pipeline to use --warn verbosity.
Today I executed ORT manually to ensure it wasn't our pipeline screwing up.
@pepper-jk pepper-jk added bug Issues that are considered to be bugs to triage Issues that need triaging labels Nov 4, 2024
@sschuberth
Copy link
Member

The interesting piece of information is

Resource [logback.xml] occurs at [jar:file:/opt/ort/lib/cli-35.0.0.jar!/logback.xml]
Resource [logback.xml] occurs at [jar:file:/opt/ort/lib/helper-cli-35.0.0.jar!/logback.xml]

We should never have both CLI entry points on the classpath, but only either or. This should not be reproducible with the plain distribution archive as this seems to be caused by the way the Dockerfile copies JARs together:

ort/Dockerfile

Lines 444 to 447 in f8a0c39

&& cp -a $HOME/src/ort/cli/build/install/ort /opt/ \
&& cp -a $HOME/src/ort/scripts/*.sh /opt/ort/bin/ \
&& cp -a $HOME/src/ort/helper-cli/build/scripts/orth /opt/ort/bin/ \
&& cp -a $HOME/src/ort/helper-cli/build/libs/helper-cli-*.jar /opt/ort/lib/

@sschuberth sschuberth added docker About Docker topics and removed to triage Issues that need triaging labels Nov 4, 2024
@sschuberth sschuberth self-assigned this Nov 4, 2024
sschuberth added a commit that referenced this issue Nov 4, 2024
@sschuberth
fix(cli): Guard against foreign classpath item with a pathing JAR
7d80174 
To not blindly add any JAR to the classpath that has been copied to the
distribution's "lib" directory, build a "pathing JAR" whose manifest
contains the intended runtime classpath. Then only use that JAR and the
main CLI JAR as the classpath for the application.

Fixes #9372.

Signed-off-by: Sebastian Schuberth <sebastian@doubleopen.org>
sschuberth added a commit that referenced this issue Nov 4, 2024
@sschuberth
fix(cli): Guard against foreign classpath item with a pathing JAR
72cff01 
To not blindly add any JAR to the classpath that has been copied to the
distribution's "lib" directory, build a "pathing JAR" whose manifest
contains the intended runtime classpath. Then only use that JAR and the
main CLI JAR as the classpath for the application.

Fixes #9372.

Signed-off-by: Sebastian Schuberth <sebastian@doubleopen.org>
sschuberth added a commit that referenced this issue Nov 5, 2024
@sschuberth
fix(cli): Guard against foreign classpath item with a pathing JAR
9bb5d10 
To not blindly add any JAR to the classpath that has been copied to the
distribution's "lib" directory, build a "pathing JAR" whose manifest
contains the intended runtime classpath. Then only use that JAR and the
main CLI JAR as the classpath for the application.

Fixes #9372.

Signed-off-by: Sebastian Schuberth <sebastian@doubleopen.org>
sschuberth added a commit that referenced this issue Nov 5, 2024
@sschuberth
fix(cli): Guard against foreign classpath items with a pathing JAR
1531644 
To not blindly add any JAR to the classpath that has been copied to the
distribution's "lib" directory, build a "pathing JAR" whose manifest
contains the intended runtime classpath. Then only use that JAR and the
main CLI JAR as the classpath for the application.

Fixes #9372.

Signed-off-by: Sebastian Schuberth <sebastian@doubleopen.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@sschuberth sschuberth

Labels
bug Issues that are considered to be bugs docker About Docker topics
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@sschuberth @pepper-jk