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

Bump logback to 1.5.3 so logging statements are printed #168

Merged
merged 1 commit into from
Mar 22, 2024

Conversation

dehall
Copy link
Contributor

@dehall dehall commented Mar 15, 2024

There are a number of logging statements in the code (for instance: https://github.com/hapifhir/org.hl7.fhir.validator-wrapper/blob/master/src/jvmMain/kotlin/controller/validation/ValidationModule.kt#L28) but as far as I can tell these don't seem to print anything anywhere. Based on the warnings printed at startup the issue seems to be that the included version of logback targets the wrong version of slf4j. This PR bumps logback to the latest release as of today, 1.5.3

Log for startup + 1 request before update:

SLF4J: No SLF4J providers were found.
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See https://www.slf4j.org/codes.html#noProviders for further details.
SLF4J: Class path contains SLF4J bindings targeting slf4j-api versions 1.7.x or earlier.
SLF4J: Ignoring binding found at [jar:file:/Users/dehall/.m2/repository/ch/qos/logback/logback-classic/1.2.3/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Ignoring binding found at [jar:file:/Users/dehall/inferno/org.hl7.fhir.validator-wrapper/build/libs/validator-wrapper-jvm-1.0.52-SNAPSHOT.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See https://www.slf4j.org/codes.html#ignoredBindings for an explanation.
Starting instance in 0.0.0.0:8082
Free memory 109317032 is less than 250000000. Re-initializing validationService
No such cached session exists for session id 6225f354-0ab0-4f04-96e9-3d93f2c3ae61, re-instantiating validator.
  Load FHIR v4.0.1 from hl7.fhir.r4.core#4.0.1 - 4576 resources (00:05.717)
  Load hl7.fhir.uv.extensions.r4#1.0.0 - 1328 resources (00:03.267)
  Load hl7.terminology#5.5.0 - 4224 resources (00:01.867)
  Load hl7.terminology.r5#5.0.0 - 4174 resources (00:00.979)
  Load hl7.fhir.uv.extensions#1.0.0 - 1328 resources (00:01.222)
  Terminology server http:https://tx.fhir.org - Version Connected to Terminology Server at http:https://tx.fhir.org (00:00.438)
  Package Summary: [hl7.fhir.r4.core#4.0.1, hl7.fhir.xver-extensions#0.1.0, hl7.fhir.uv.extensions.r4#1.0.0, hl7.terminology#5.5.0, hl7.terminology.r5#5.0.0, hl7.fhir.uv.extensions#1.0.0]
  Get set...  go (00:00.312)
  .. validate Observation/798.json
Validate Observation against http:https://hl7.org/fhir/StructureDefinition/Observation|4.0.1..........20..........40..........60..........80.........|
  Max Memory: 8589934592

Log for startup + 1 request after update: (there is a lot more init-type logging but it may be possible to disable that)

10:12:40,392 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.5.3
10:12:40,393 |-INFO in ch.qos.logback.classic.util.ContextInitializer@31190526 - No custom configurators were discovered as a service.
10:12:40,393 |-INFO in ch.qos.logback.classic.util.ContextInitializer@31190526 - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
10:12:40,394 |-INFO in ch.qos.logback.classic.util.ContextInitializer@31190526 - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
10:12:40,399 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
10:12:40,399 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
10:12:40,406 |-INFO in ch.qos.logback.classic.util.ContextInitializer@31190526 - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 6 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
10:12:40,406 |-INFO in ch.qos.logback.classic.util.ContextInitializer@31190526 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
10:12:40,406 |-INFO in ch.qos.logback.classic.util.ContextInitializer@31190526 - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
10:12:40,407 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
10:12:40,409 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/Users/dehall/inferno/org.hl7.fhir.validator-wrapper/build/processedResources/jvm/main/logback.xml]
10:12:40,410 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@662ac478 - Resource [logback.xml] occurs multiple times on the classpath.
10:12:40,410 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@662ac478 - Resource [logback.xml] occurs at [file:/Users/dehall/inferno/org.hl7.fhir.validator-wrapper/build/processedResources/jvm/main/logback.xml]
10:12:40,410 |-WARN in ch.qos.logback.classic.util.DefaultJoranConfigurator@662ac478 - Resource [logback.xml] occurs at [jar:file:/Users/dehall/inferno/org.hl7.fhir.validator-wrapper/build/libs/validator-wrapper-jvm-1.0.52-SNAPSHOT.jar!/logback.xml]
10:12:40,504 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [STDOUT]
10:12:40,504 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
10:12:40,511 |-INFO in ch.qos.logback.core.model.processor.ImplicitModelHandler - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
10:12:40,535 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to INFO
10:12:40,535 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [STDOUT] to Logger[ROOT]
10:12:40,535 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@6743e411 - End of configuration.
10:12:40,536 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@3eb25e1a - Registering current configuration as safe fallback point
10:12:40,536 |-INFO in ch.qos.logback.classic.util.ContextInitializer@31190526 - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 130 milliseconds. ExecutionStatus=DO_NOT_INVOKE_NEXT_IF_ANY

2024-03-15 10:12:40.629 [main] INFO  org.eclipse.jetty.util.log - Logging initialized @733ms to org.eclipse.jetty.util.log.Slf4jLog
2024-03-15 10:12:40.700 [main] INFO  ktor.application - Autoreload is disabled because the development mode is off.
Starting instance in 0.0.0.0:8082
2024-03-15 10:12:41.119 [main] INFO  ktor.application - Application started in 0.551 seconds.
2024-03-15 10:12:41.119 [main] INFO  ktor.application - Application starting: io.ktor.server.application.Application@1436a7ab
2024-03-15 10:12:41.119 [main] INFO  ktor.application - Application started: io.ktor.server.application.Application@1436a7ab
2024-03-15 10:12:41.120 [main] INFO  ktor.application - Application started: io.ktor.server.application.Application@1436a7ab
2024-03-15 10:12:41.123 [main] INFO  org.eclipse.jetty.server.Server - jetty-9.4.45.v20220203; built: 2022-02-03T09:14:34.105Z; git: 4a0c91c0be53805e3fcffdcdcc9587d5301863db; jvm 17.0.8+7
2024-03-15 10:12:41.157 [main] INFO  o.e.jetty.server.AbstractConnector - Started ServerConnector@6b0d80ed{HTTP/1.1, (http/1.1, h2c)}{0.0.0.0:8082}
2024-03-15 10:12:41.158 [main] INFO  org.eclipse.jetty.server.Server - Started @1265ms
2024-03-15 10:12:41.160 [DefaultDispatcher-worker-1] INFO  ktor.application - Responding at http:https://0.0.0.0:8082
2024-03-15 10:13:20.081 [ktor-jetty-8082-2] INFO  ktor.application - Received Validation Request. FHIR Version: 4.0.1 IGs: [] Memory (free/max): 99266016/8589934592
Free memory 97059728 is less than 250000000. Re-initializing validationService
No such cached session exists for session id 6225f354-0ab0-4f04-96e9-3d93f2c3ae61, re-instantiating validator.
  Load FHIR v4.0.1 from hl7.fhir.r4.core#4.0.1 - 4576 resources (00:06.088)
  Load hl7.fhir.uv.extensions.r4#1.0.0 - 1328 resources (00:04.951)
  Load hl7.terminology#5.5.0 - 4224 resources (00:01.724)
  Load hl7.terminology.r5#5.0.0 - 4174 resources (00:01.261)
  Load hl7.fhir.uv.extensions#1.0.0 - 1328 resources (00:01.615)
  Terminology server http:https://tx.fhir.org - Version Connected to Terminology Server at http:https://tx.fhir.org (00:00.486)
  Package Summary: [hl7.fhir.r4.core#4.0.1, hl7.fhir.xver-extensions#0.1.0, hl7.fhir.uv.extensions.r4#1.0.0, hl7.terminology#5.5.0, hl7.terminology.r5#5.0.0, hl7.fhir.uv.extensions#1.0.0]
  Get set...  go (00:00.482)
  .. validate Observation/798.json
Validate Observation against http:https://hl7.org/fhir/StructureDefinition/Observation|4.0.1..........20..........40..........60..........80.........|
  Max Memory: 8589934592
2024-03-15 10:13:37.674 [ktor-jetty-8082-4] INFO  ktor.application - 200 OK: POST - /validate

@dotasek dotasek self-requested a review March 22, 2024 21:24
Copy link
Collaborator

@dotasek dotasek left a comment

Choose a reason for hiding this comment

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

Nice. Thanks for catching this.

@dotasek dotasek merged commit ebdff01 into hapifhir:master Mar 22, 2024
5 checks passed
markiantorno added a commit that referenced this pull request Apr 8, 2024
* Bump core version
* Allow prerelease IGs (#171)
* Bump logback to 1.5.3 (#168)
***NO_CI***
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants