Can we have consistent SLF4J logging throughout all components ?

michael.renaud · April 26, 2017, 9:02am

Hi

An annoying thing using CUBA is the logging :

tomcat uses this horrible and performance hog that is JUL
same for Vaadin
Spring uses JCL
CUBA classes uses slf4j over logback
and for some reason, my own classes not extending CUBA ones are not using SLF4J

I think that 90% of users around the planet want to have a single Logging framework for each and every component. The others 10% simply do not have a choice. I also think that there should be an option when setting up CUBA platform to have it configure SLF4J/logback everywhere.

If you look at the console output at the end of this post, you can see the different logging frameworks writing throughout it, this is a mess. More annoying situation is the one depicted by the lines in bold in the log : my own classes, depending if they are derived from standard CUBA classes (e.g ExtAppMainWindow) or not (e.g EntityRules) are not using the same framework.

And they are getting logger instances the same way, both in web module :


    private final static Logger log = LoggerFactory.getLogger(EntityRules.class);
    private final static Logger log = LoggerFactory.getLogger(ExtAppMainWindow.class);

So I spent hours trying to have SLF4J everywhere, but what is painful is that you have a specific procedure for every component : Tomcat, Spring, Vaadin. And for my own classes not extending CUBA ones, I do not even know what to do.

I tried to setup tomcat log to SLF4J but none of the solutions you find on the net really work out-of-the-box. I also tried to setup Vaadin to log through SLF4J but for that one needs to access the main UI class to put the code below. And this UI class is buried into CUBA framework.


static {
    SLF4JBridgeHandler.removeHandlersForRootLogger();
    SLF4JBridgeHandler.install();
  }

I then tried to put this code in AppLifeCycle context listener : no effect. I really do not understand why CUBA SLF4J/logback configuration is not defined to be used by, at the very least, Spring and classes except CUBA.

Log output (tried my best to make it readable, but markdown is a pain with that kind of text)


    avr. 26, 2017 10:32:28 AM org.apache.catalina.startup.VersionLoggerListener log
    INFOS: Server version:        Apache Tomcat/8.5.9
    ...
    avr. 26, 2017 10:32:28 AM org.apache.catalina.core.ApplicationContext log
    INFOS: Initializing AtmosphereFramework
    avr. 26, 2017 10:32:28 AM org.apache.catalina.core.ApplicationContext log
    INFOS: No Spring WebApplicationInitializer types detected on classpath
    avr. 26, 2017 10:32:29 AM org.atmosphere.cpr.AtmosphereFramework addAtmosphereHandler
    INFOS: Installed AtmosphereHandler com.vaadin.server.communication.PushAtmosphereHandler mapped to context-path: 
    avr. 26, 2017 10:32:29 AM org.atmosphere.cpr.AtmosphereFramework addAtmosphereHandler
    ...
    avr. 26, 2017 10:32:29 AM org.atmosphere.cpr.AtmosphereFramework interceptor
    INFOS: Installed AtmosphereInterceptor  Track Message Size Interceptor using | with priority BEFORE_DEFAULT 
    10:32:29.103 INFO  c.h.cuba.core.sys.AppComponents - Using app components: &#91;com.haulmont.cuba, com.haulmont.reports,     com.haulmont.fts, com.haulmont.charts&#93;
    10:32:29.153 INFO  c.h.cuba.web.sys.WebAppContextLoader - Loading app properties from classpath:cuba-web-app.properties
    10:32:29.153 INFO  c.h.cuba.web.sys.WebAppContextLoader - Loading app properties from classpath:com/busy/app/web-app.properties
    ...
    10:32:31.501 INFO  c.h.cuba.web.sys.WebAppContextLoader - AppContext initialized
    avr. 26, 2017 10:32:31 AM org.apache.catalina.core.ApplicationContext log
    INFOS: Initializing Spring FrameworkServlet 'dispatcher'
    10:32:31.522 INFO  c.h.c.web.sys.CubaDispatcherServlet - FrameworkServlet 'dispatcher': initialization started
    10:32:31.525 INFO  c.h.c.c.s.CubaXmlWebApplicationContext - Refreshing WebApplicationContext for namespace 'dispatcher-servlet': startup     date &#91;Wed Apr 26 10:32:31 CEST 2017&#93;; parent: com.haulmont.cuba.core.sys.CubaClassPathXmlApplicationContext@3d01c73
    10:32:32.228 INFO  c.h.c.web.sys.CubaDispatcherServlet - FrameworkServlet 'dispatcher': initialization completed in 706 ms
    avr. 26, 2017 10:32:32 AM org.apache.catalina.core.ApplicationContext log
    INFOS: Initializing Spring FrameworkServlet 'rest_api'
    10:32:32.229 INFO  c.h.restapi.sys.CubaRestApiServlet - FrameworkServlet 'rest_api': initialization started
    10:32:32.229 INFO  c.h.c.c.s.CubaXmlWebApplicationContext - Refreshing WebApplicationContext for namespace 'rest_api-servlet': startup date     &#91;Wed Apr 26 10:32:32 CEST 2017&#93;; parent: com.haulmont.cuba.core.sys.CubaClassPathXmlApplicationContext@3d01c73
    10:32:33.032 INFO  c.h.restapi.sys.CubaRestApiServlet - FrameworkServlet 'rest_api': initialization completed in 803 ms
    avr. 26, 2017 10:32:33 AM org.apache.catalina.startup.HostConfig deployDirectory
    INFOS: Deployment of web application directory D:\dev\studio-projects\busy\deploy\tomcat\webapps\app has finished in 4 490 ms
    avr. 26, 2017 10:32:33 AM org.apache.catalina.startup.HostConfig deployDirectory
    INFOS: Déploiement du répertoire D:\dev\studio-projects\busy\deploy\tomcat\webapps\app-core de l'application web
    avr. 26, 2017 10:32:33 AM org.apache.catalina.core.ApplicationContext log
    INFOS: Initializing AtmosphereFramework
    avr. 26, 2017 10:32:33 AM org.apache.catalina.core.ApplicationContext log
    INFOS: No Spring WebApplicationInitializer types detected on classpath
    10:32:33.120 INFO  c.h.cuba.core.sys.AppComponents - Using app components: &#91;com.haulmont.cuba, com.haulmont.reports,     com.haulmont.fts, com.haulmont.charts&#93;
    10:32:33.125 INFO  c.h.cuba.core.sys.AppContextLoader - Loading app properties from classpath:cuba-app.properties
    10:32:33.125 INFO  c.h.cuba.core.sys.AppContextLoader - Loading app properties from classpath:com/busy/app/app.properties
    ...
    10:32:38.839 INFO  c.h.cuba.core.sys.AppContextLoader - AppContext initialized
    avr. 26, 2017 10:32:38 AM org.apache.catalina.core.ApplicationContext log
    INFOS: Initializing Spring FrameworkServlet 'remoting'
    10:32:38.842 INFO  c.h.c.c.sys.remoting.RemotingServlet - FrameworkServlet 'remoting': initialization started
    10:32:38.843 INFO  c.h.c.c.s.CubaDefaultXmlWebApplicationContext - Refreshing WebApplicationContext for namespace 'remoting-servlet':     startup date &#91;Wed Apr 26 10:32:38 CEST 2017&#93;; parent: com.haulmont.cuba.core.sys.CubaCoreApplicationContext@75c7bdb4
    10:32:38.858 INFO  c.h.c.c.s.r.RemoteServicesBeanCreator - Configuring remote services
    10:32:38.939 INFO  c.h.c.c.sys.remoting.RemotingServlet - FrameworkServlet 'remoting': initialization completed in 97 ms
    avr. 26, 2017 10:32:38 AM org.apache.catalina.startup.HostConfig deployDirectory
    INFOS: Deployment of web application directory D:\dev\studio-projects\busy\deploy\tomcat\webapps\app-core has finished in 5 899 ms
    avr. 26, 2017 10:32:38 AM org.apache.coyote.AbstractProtocol start
    ...
    avr. 26, 2017 10:32:38 AM org.apache.catalina.startup.Catalina start
    INFOS: Server startup in 10421 ms
    10:32:38.997 INFO  c.h.c.security.app.LoginWorkerBean - Logged in: 926e743b-d42a-8a03-472b-ade3dcee4b97 &#91;admin&#93;
    avr. 26, 2017 10:33:03 AM com.vaadin.server.DefaultDeploymentConfiguration checkProductionMode
    AVERTISSEMENT: 
    =================================================================
    Vaadin is running in DEBUG MODE.
    Add productionMode=true to web.xml to disable debug features.
    To show debug window, add ?debug to your application URL.
    =================================================================
    10:33:03.703 INFO  c.h.cuba.core.sys.MetadataImpl - Initializing metadata
    ...
    10:33:03.844 INFO  c.h.cuba.core.sys.MetadataImpl - Metadata initialized in 141ms
    10:33:08.406 INFO  c.h.c.security.app.LoginWorkerBean - Logged in: 4bb99744-6c12-9895-1069-5303602fcc7c &#91;admin&#93;
    10:33:08.506 INFO  c.h.c.c.sys.ViewRepositoryClientImpl - Initializing views

<b>10:33:08.745 INFO  c.b.app.web.screens.ExtAppMainWindow - EAMWLS : com.busy.app.service.LogInterceptor@75b5629</b>
<b>10:33:08.745 INFO  c.b.app.web.screens.ExtAppMainWindow - EAMWLSEB : com.busy.app.events.GlobalEventBus@2552ac9f</b>

    10:33:12.550 INFO  c.h.cuba.core.app.PersistenceManager - Loading statistics cache
    10:33:12.607 INFO  c.h.cuba.core.sys.ViewRepositoryImpl - Initializing views
    ready

<b>avr. 26, 2017 10:33:14 AM com.busy.app.web.guirules.EntityRules initFieldGroup</b>
<b>AVERTISSEMENT: Field spec not applied for property 'accountingPlan', unable to guess component kind for component     com.haulmont.cuba.web.gui.components.WebLookupPickerField@475ebe25</b>

    10:33:14.245 INFO  c.busy.app.web.customer.CustomerEdit - CE : com.busy.app.events.GlobalEventBus@2552ac9f
    10:33:14.245 INFO  c.busy.app.web.customer.CustomerEdit - CELS : com.busy.app.service.LogInterceptor@75b5629
    10:33:14.245 INFO  c.busy.app.web.customer.CustomerEdit - CELSEB : com.busy.app.events.GlobalEventBus@2552ac9f
    avr. 26, 2017 10:33:22 AM org.apache.coyote.AbstractProtocol pause
    INFOS: Pausing ProtocolHandler &#91;"http-nio-8080"&#93;
    ...

michael.renaud · May 1, 2017, 4:09pm

Finally managed to have all logs go through SLF4J. I have written a procedure (attachment) and tested it successfully on a small sample project.

However, when building from Studio, sometimes it erases all the modifications I made to Tomcat files.

I would be glad to hear from experts around here on this procedure. And how can I make it resistant to rebuild in Studio (maybe creating a post deploy task in Gradle ?).

Mike

CUBA-6.4-all-logs-to-slf4j-logback.zip (736.9K)

artamonov · May 27, 2017, 12:50pm

Hi!

Thank you for this investigation! I’ve created an issue on that https://youtrack.cuba-platform.com/issue/PL-9169. We will try to tune these settings in the next minor release of the platform.