search

odpi / egeria

Egeria core
https://egeria-project.org
Apache License 2.0
806 stars 260 forks source link

Superfluous developer logging at OMAG Server Platform start #4323

Closed mandy-chessell closed 3 years ago

mandy-chessell commented 3 years ago

By default the developer logging (SLF4J) is turned off so that debug logging dows not swamp messages to end user. We allowed the 2 log messages from the web server to document the port being used but nothing else.

However, just recently I see a lot of superflous log entries coming out ... and the port entries seem to have gone. Has something changed? How do we put it back to where it was.

15:19:36,436 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
15:19:36,440 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
15:19:36,440 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/Users/mandy-chessell/CloudStation/Drive/Code/ODPi/egeria-code/egeria/open-metadata-implementation/server-chassis/server-chassis-spring/target/classes/logback.xml]
15:19:36,448 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs multiple times on the classpath.
15:19:36,448 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [file:/Users/mandy-chessell/CloudStation/Drive/Code/ODPi/egeria-code/egeria/open-metadata-implementation/server-chassis/server-chassis-spring/target/classes/logback.xml]
15:19:36,448 |-WARN in ch.qos.logback.classic.LoggerContext[default] - Resource [logback.xml] occurs at [file:/Users/mandy-chessell/CloudStation/Drive/Code/ODPi/egeria-code/egeria/open-metadata-resources/open-metadata-archives/open-metadata-types/target/classes/logback.xml]
15:19:36,855 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
15:19:36,906 |-INFO in ch.qos.logback.core.joran.util.ConfigurationWatchListUtil@4d154ccd - Adding [jar:file:/Users/mandy-chessell/.m2/repository/org/springframework/boot/spring-boot/2.3.3.RELEASE/spring-boot-2.3.3.RELEASE.jar!/org/springframework/boot/logging/logback/base.xml] to configuration watch list.
15:19:36,906 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@229c6181 - URL [jar:file:/Users/mandy-chessell/.m2/repository/org/springframework/boot/spring-boot/2.3.3.RELEASE/spring-boot-2.3.3.RELEASE.jar!/org/springframework/boot/logging/logback/base.xml] is not of type file
15:19:36,912 |-INFO in ch.qos.logback.core.joran.util.ConfigurationWatchListUtil@4d154ccd - Adding [jar:file:/Users/mandy-chessell/.m2/repository/org/springframework/boot/spring-boot/2.3.3.RELEASE/spring-boot-2.3.3.RELEASE.jar!/org/springframework/boot/logging/logback/defaults.xml] to configuration watch list.
15:19:36,912 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@229c6181 - URL [jar:file:/Users/mandy-chessell/.m2/repository/org/springframework/boot/spring-boot/2.3.3.RELEASE/spring-boot-2.3.3.RELEASE.jar!/org/springframework/boot/logging/logback/defaults.xml] is not of type file
15:19:36,918 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word clr with class [org.springframework.boot.logging.logback.ColorConverter]
15:19:36,918 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word wex with class [org.springframework.boot.logging.logback.WhitespaceThrowableProxyConverter]
15:19:36,918 |-INFO in ch.qos.logback.core.joran.action.ConversionRuleAction - registering conversion word wEx with class [org.springframework.boot.logging.logback.ExtendedWhitespaceThrowableProxyConverter]
15:19:36,946 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.catalina.startup.DigesterFactory] to ERROR
15:19:36,946 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.catalina.util.LifecycleBase] to ERROR
15:19:36,947 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.coyote.http11.Http11NioProtocol] to WARN
15:19:36,947 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.sshd.common.util.SecurityUtils] to WARN
15:19:36,947 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.apache.tomcat.util.net.NioSelectorPool] to WARN
15:19:36,947 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.eclipse.jetty.util.component.AbstractLifeCycle] to ERROR
15:19:36,947 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.hibernate.validator.internal.util.Version] to WARN
15:19:36,947 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.springframework.boot.actuate.endpoint.jmx] to WARN
15:19:36,947 |-INFO in ch.qos.logback.core.joran.util.ConfigurationWatchListUtil@4d154ccd - Adding [jar:file:/Users/mandy-chessell/.m2/repository/org/springframework/boot/spring-boot/2.3.3.RELEASE/spring-boot-2.3.3.RELEASE.jar!/org/springframework/boot/logging/logback/console-appender.xml] to configuration watch list.
15:19:36,947 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@229c6181 - URL [jar:file:/Users/mandy-chessell/.m2/repository/org/springframework/boot/spring-boot/2.3.3.RELEASE/spring-boot-2.3.3.RELEASE.jar!/org/springframework/boot/logging/logback/console-appender.xml] is not of type file
15:19:36,952 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
15:19:36,979 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CONSOLE]
15:19:37,022 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
15:19:37,299 |-INFO in ch.qos.logback.core.joran.util.ConfigurationWatchListUtil@4d154ccd - Adding [jar:file:/Users/mandy-chessell/.m2/repository/org/springframework/boot/spring-boot/2.3.3.RELEASE/spring-boot-2.3.3.RELEASE.jar!/org/springframework/boot/logging/logback/file-appender.xml] to configuration watch list.
15:19:37,299 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@229c6181 - URL [jar:file:/Users/mandy-chessell/.m2/repository/org/springframework/boot/spring-boot/2.3.3.RELEASE/spring-boot-2.3.3.RELEASE.jar!/org/springframework/boot/logging/logback/file-appender.xml] is not of type file
15:19:37,303 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
15:19:37,313 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [FILE]
15:19:37,319 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
15:19:37,342 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1183231938 - setting totalSizeCap to 0 Bytes
15:19:37,357 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1183231938 - Archive files will be limited to [10 MB] each.
15:19:37,374 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1183231938 - Will use gz compression
15:19:37,380 |-INFO in c.q.l.core.rolling.SizeAndTimeBasedRollingPolicy@1183231938 - Will use the pattern /var/folders/cp/ssr8gm_x0j3fknbhtqrmrr6m0000gn/T//spring.log.%d{yyyy-MM-dd}.%i for the active file
15:19:37,391 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@1e0b4072 - The date pattern is 'yyyy-MM-dd' from file name pattern '/var/folders/cp/ssr8gm_x0j3fknbhtqrmrr6m0000gn/T//spring.log.%d{yyyy-MM-dd}.%i.gz'.
15:19:37,391 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@1e0b4072 - Roll-over at midnight.
15:19:37,391 |-INFO in ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP@1e0b4072 - Setting initial period to Tue Dec 15 15:19:36 GMT 2020
15:19:37,434 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - Active log file name: /var/folders/cp/ssr8gm_x0j3fknbhtqrmrr6m0000gn/T//spring.log
15:19:37,434 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[FILE] - File property is set to [/var/folders/cp/ssr8gm_x0j3fknbhtqrmrr6m0000gn/T//spring.log]
15:19:37,442 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
15:19:37,442 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CONSOLE] to Logger[ROOT]
15:19:37,446 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [FILE] to Logger[ROOT]
15:19:37,446 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
15:19:37,450 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@791f145a - Registering current configuration as safe fallback point
mandy-chessell commented 3 years ago

Actually, the port messages are coming out ok - so that part is not a problem :)

bogdan-sava commented 3 years ago

I am happy to create PR for this. Obviously, issues may be fixed in many ways.

The issue is: We are packaging in server-chassis at least 2 classes with main methods. Default spring-boot-one and the one from open-metadata-types module in OpenMetadataTypesArchiveWriter. As we want to be able to run the OpenMetadataTypesArchiveWriter main outside the server-chassis and silent logging, we added configuration file in the resource file. But this configuration file affects server-chassis as it is added in the classpath.

Solution 1 We keep main method and the writer in the open-metadata-types but rename configuration file ( ex: logback-om.xml ) and loaded on runtime only for this main, and is going to be ignored by server-chassis. Also allowing override it in command line.

Solution 2 Remove the main method and logback.xml from open-metadata-types module and create a dedicated module, for example egeria-cli where we add a main for write the archive as json and maybe other utility main functions.

I'll go for the sake of time with solution 1 and if we decide that solution 2 is better, I will refactor it. Both are easy implementations.

bogdan-sava commented 3 years ago

As a good practice we shouldn't add logback.xml files in modules. Especially if we want the modules to be hosted in other applications. If the host application is using logback for logging, our jar could mess up host logging as happened with server-chassis which in this case is the host for open-metadata-types.

logback.xml suppose to be where the java process starts. That was the problem. But we have lot more logback.xml files spread over. They should be removed if we want to be good citizens.

planetf1 commented 3 years ago

In #3392 the observation of an overriding logback.xml was made and the proposal there was to do the split as @bogdan-sava proposes - but it wasn't actioned at that point.

I provided an explanation there .. and the proposal was item 2 - However I don't see any big issue with going with 1 as an interim measure as it will prevent the log xml 'contamination' - though in many ways it is more complex (code). The root cause was having a module with dual roles - both that of a library & an executable, since as mentioned above, we should only include logging implementation when building 'executables' and not libraries (which imo is an anti pattern)

That being said, the logback configuration (now renamed) in the open metadata types module is setting log level to OFF - so would not explain the 'INFO' messages we see in the original posted problem

As such either a) Some additional local configuration (like the env var LOGGING_LEVEL_ROOT) is set to include info b) The configuration is being picked up from another logback.xml (or another slf4j logging implementation)

So whilst the fix does help prevent future errors, a) we should go further as split role can cause other issues and more crucially b) I don't see how it fixes the original issue (but I may have missed something)

planetf1 commented 3 years ago

But we have lot more logback.xml files spread over. They should be removed if we want to be good citizens. They should only be included in application modules (ie where we have a main).

Currently I see:

jonesn:egeria/ (master) $ find . -name 'logback.xml' | grep src                                        [9:13:43]
./open-metadata-resources/open-metadata-archives/open-connector-archives/src/main/resources/logback.xml
./open-metadata-resources/open-metadata-archives/open-metadata-types/src/main/resources/logback.xml
./open-metadata-resources/open-metadata-archives/design-model-archives/glossary-canonical-model/src/main/resources/logback.xml
./open-metadata-resources/open-metadata-archives/design-model-archives/cloud-information-model/src/main/resources/logback.xml
./open-metadata-resources/open-metadata-samples/access-services-samples/subject-area-client-samples/subject-area-definition-sample/src/main/resources/logback.xml
./open-metadata-resources/open-metadata-samples/access-services-samples/asset-management-samples/asset-reader-avro-sample/src/main/resources/logback.xml
./open-metadata-resources/open-metadata-samples/access-services-samples/asset-management-samples/asset-create-avro-sample/src/main/resources/logback.xml
./open-metadata-resources/open-metadata-samples/access-services-samples/asset-management-samples/asset-create-csv-sample/src/main/resources/logback.xml
./open-metadata-resources/open-metadata-samples/access-services-samples/asset-management-samples/asset-reader-csv-sample/src/main/resources/logback.xml
./open-metadata-resources/open-metadata-samples/access-services-samples/governance-program-client-samples/governance-leadership-sample/src/main/resources/logback.xml
./open-metadata-resources/open-metadata-samples/access-services-samples/governance-program-client-samples/governance-zone-create-sample/src/main/resources/logback.xml
./open-metadata-resources/open-metadata-samples/admin-services-samples/admin-services-config-metadata-server-sample/src/main/resources/logback.xml
./open-metadata-conformance-suite/open-metadata-conformance-suite-client/src/main/resources/logback.xml
./open-metadata-implementation/server-chassis/server-chassis-spring/src/main/resources/logback.xml

which I think are just either utilities (ie CIM, glossary models), samples (with a main), our server chassis, CTS client - apart from the module referred to above

planetf1 commented 3 years ago

The actual cause of the INFO files is the change in server-chassis-spring. Under src/main/resources we now have a logback.xml which includes:

<configuration>
     <include resource="org/springframework/boot/logging/logback/base.xml"/>
 </configuration>

this uses the default config as at https://github.com/spring-projects/spring-boot/blob/master/spring-boot-project/spring-boot/src/main/resources/org/springframework/boot/logging/logback/base.xml which we note has:

    <root level="INFO">
        <appender-ref ref="CONSOLE" />
        <appender-ref ref="FILE" />
    </root>

So THAT is the cause of the change - NOT the component mentioned above (though there was POTENTIAL for mess ups there, and the change to server chassis was prompted by that underlaying problem)

This was introduced in https://github.com/odpi/egeria/commit/3e71bc9e898ee4713f0498d9b64abd0cfb35cdb6.

Sticking with default format seems appropriate, but it had the inadvertant effect of resetting the logging levels cc: @lpalashevski

lpalashevski commented 3 years ago

The change was discussed and captured under #4162 point (1), adding logback.xml to server-chassis-spring was the first step to revert to default spring logging on application level and compensate for the fact that some of the modules/libaries override this cofiguration.

For long term solution we also agreed that we want to fix this across the other modules (one example is open-metadata-types) and follow the agreed best practice not to have logging configuration embedded in libraries but leave this as reposnibility of the application/container/environment (sprit roles like Nigel called it)

I aggree with both solutions suggested by Bogdan but for now since I do not know the impact and how much work will be to achieve Soulution 2 as interim I would go with Solution 1.

bogdan-sava commented 3 years ago

Adding a logback.xml in the spring-boot app was an workaround because logging was messed up by the lognback.xml in the module. As a matter of fact, I can remove it as the part of PR.

So:

  1. spring-boot app is the host app that useed default logback config, without logback.xml
  2. in the module was added logback.xml that messed up spring-boot logging
  3. we added logback.xml in spring-boot to override once again configuration and get back to defaul. This last step added superfluous logging because there are "more than one config file in classpath"

As part of the solution in PR:

  1. renamed logback.xml from module to be used only in the main not messing up host logging
  2. I will remove logback.xml as not needed anymore
bogdan-sava commented 3 years ago

Done! I removed logback.xml from server-chassis and works just fine, because default are not override by module.

And again: it happened with server-chassis but it will happen with all host applications that are using logback for logging and include a module with another one in it.