stack traces from Tomcat 10.1.12
Hi all, I've noticed these stack traces happening in the same row with Tomcat 10.1.12, Java 17 and Spring Boot 3.1.3. I don't have a way to reproduce them unfortunately. I thought that it could be related to https://bz.apache.org/bugzilla/show_bug.cgi?id=67235 but not sure. Sharing them here in case it could be useful to pinpoint any issue in case these are not already fixed in current development branch of Tomcat or its latest version. Thank you! Best regards, Tomás Stacktraces: logger org.apache.catalina.connector.CoyoteAdapter messageException while processing an asynchronous request java.lang.IllegalStateException: Calling [asyncComplete()] is not valid for a request with Async state [COMPLETING] at org.apache.coyote.AsyncStateMachine.asyncComplete(AsyncStateMachine.java:345) at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:508) at org.apache.coyote.Request.action(Request.java:514) at org.apache.catalina.core.AsyncContextImpl.complete(AsyncContextImpl.java:91) at org.apache.catalina.core.AsyncContextImpl.setErrorState(AsyncContextImpl.java:427) at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:155) at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:243) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:57) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:894) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1740) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.base/java.lang.Thread.run(Thread.java:833) logger org.apache.coyote.http11.Http11NioProtocol messageError reading request, ignored java.lang.NullPointerException: Cannot invoke "org.apache.catalina.Context.bind(boolean, java.lang.ClassLoader)" because "this.context" is null at org.apache.catalina.core.AsyncContextImpl.fireOnComplete(AsyncContextImpl.java:101) at org.apache.coyote.AsyncStateMachine.asyncPostProcess(AsyncStateMachine.java:286) at org.apache.coyote.AbstractProcessor.asyncPostProcess(AbstractProcessor.java:197) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:78) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:894) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1740) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.base/java.lang.Thread.run(Thread.java:833) - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Migrating Tomcat 8/9 and a single webapp to Java 17 disconfigures Tomcat logs
Alcides, On 9/28/23 14:55, Alcides Moraes wrote: Hello everyone, I’m new to the list even though I’ve been a Java web developer for many years, I’ve never had the need to post here, but this time I think I may have stumbled upon a bug, and nothing turns up online on this issue. We’re migrating our containerized legacy webapps from Java 8/11 to Java 17. They all ran on Tomcat 8.5, now we’re upgrading to 9. We customize a base image from tomcat:9.0.80-jdk17-temurin-focal. Amongst other things, we add a logging.properties to customize tomcat’s log format. This always worked well, but after our upgrade to Java 17, there’s a weird behavior that has stumped us. During Tomcat’s startup, the logs are formatted correctly as we specify in logging.properties. However, after a certain point in the logs, the logs revert to the “default” JUL/JULI format. Apart from this, everything works as expected. But we need the formatted logs because we parse them with LogStash and OpenSearch. Here’s an excerpt of the logs when this happens: local-corporativo-comum-1 | 2023-09-27T18:57:34.188 INFO [org.apache.coyote.http11.Http11NioProtocol] (thread-1) Initializing ProtocolHandler ["http-nio-8080"] local-corporativo-comum-1 | 2023-09-27T18:57:34.266 INFO [org.apache.catalina.startup.Catalina] (thread-1) Server initialization in [3419] milliseconds local-corporativo-comum-1 | 2023-09-27T18:57:34.606 INFO [com.hazelcast.config.UrlXmlConfig] (thread-1) Configuring Hazelcast from 'file:/usr/local/tomcat/conf/hazelcast-local.xml'. local-corporativo-comum-1 | 2023-09-27T18:57:36.775 INFO [org.apache.catalina.core.StandardService] (thread-1) Starting service [Catalina] local-corporativo-comum-1 | 2023-09-27T18:57:36.789 INFO [org.apache.catalina.core.StandardEngine] (thread-1) Starting Servlet engine: [Secure Web Server] local-corporativo-comum-1 | 2023-09-27T18:57:36.863 INFO [org.apache.catalina.startup.HostConfig] (thread-1) Diretório de instalação da aplicação web [/usr/local/tomcat/webapps/corporativo-comum] local-corporativo-comum-1 | 2023-09-27T18:57:52.647 INFO [br.leg.senado.util.tomcat.DataSourceFactory] (thread-1) Criando instância do datasource corporativo-comumDS local-corporativo-comum-1 | set. 27, 2023 6:57:55 PM br.leg.senado.util.tomcat.DataSourceFactory getObjectInstance local-corporativo-comum-1 | INFORMAÇÕES: Criando instância do datasource monitoraaplDS local-corporativo-comum-1 | set. 27, 2023 6:57:55 PM org.apache.catalina.core.ApplicationContext log local-corporativo-comum-1 | INFORMAÇÕES: 1 Spring WebApplicationInitializers detected on classpath local-corporativo-comum-1 | set. 27, 2023 6:57:55 PM org.apache.catalina.core.ApplicationContext log local-corporativo-comum-1 | INFORMAÇÕES: Initializing Spring root WebApplicationContext local-corporativo-comum-1 | 18:57:55.751 [main] INFO org.springframework.web.context.ContextLoader - Root WebApplicationContext: initialization started The red text is tomcat logging using the defaults (which localize log levels to our locale which is pt-br). I suspect that the point where this happens is when the webapp is being initialized. A webapp shouldn’t be able to interfere with Tomcat’s log behavior, right? The webapp does not use JUL, it uses logback, and it logs correctly during and after its startup. The logs you see @ 18:57:52 that says “Criando instância...” are of custom datasource resources specified in a context.xml file. They have a custom factory class, passed from a custom jar in tomcat's class path. This jar has worked and logged correctly since ever, we didn’t even recompile them to Java 17, we kept them as they were (Java 8). I’ve tried changing the way this component logs, by calling org.apache.juli instead of java.util.logging, removed all logging whatsoever, but nothing changes this behavior. Any suggestions on debugging this? If you need more info don’t hesitate to ask. Thanks in advance for any help on this. I feel like I've heard of things like this happening before. It had something to do with an application re-initializing and having a private logging.properties file which ended up updating the global logging configuration. Can you search the entire (container's) disk for logging.properties files /and also all the JAR files you are using/ to see if there is a stray file somewhere that could be picked-up at some point after initial boot? -chris - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: stack traces from Tomcat 10.1.12
Thomás, On 9/29/23 03:03, Tomás García wrote: I've noticed these stack traces happening in the same row with Tomcat 10.1.12, Java 17 and Spring Boot 3.1.3. I don't have a way to reproduce them unfortunately. I thought that it could be related to https://bz.apache.org/bugzilla/show_bug.cgi?id=67235 but not sure. Sharing them here in case it could be useful to pinpoint any issue in case these are not already fixed in current development branch of Tomcat or its latest version. Can you provide any more context? I don't see, for example, any application code in these stack traces which means something has caused Tomcat's own internal async state tracking to get confused about something. Are you using application-managed threads to handle your async requests? Can you provide some sample code for how you use them? Do these errors happen at arbitrary times, or could they be happening around application re-deployment, Tomcat shut-down, etc.? Anything else you could provide which would help? -chris Stacktraces: logger org.apache.catalina.connector.CoyoteAdapter messageException while processing an asynchronous request java.lang.IllegalStateException: Calling [asyncComplete()] is not valid for a request with Async state [COMPLETING] at org.apache.coyote.AsyncStateMachine.asyncComplete(AsyncStateMachine.java:345) at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:508) at org.apache.coyote.Request.action(Request.java:514) at org.apache.catalina.core.AsyncContextImpl.complete(AsyncContextImpl.java:91) at org.apache.catalina.core.AsyncContextImpl.setErrorState(AsyncContextImpl.java:427) at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:155) at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:243) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:57) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:894) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1740) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.base/java.lang.Thread.run(Thread.java:833) logger org.apache.coyote.http11.Http11NioProtocol messageError reading request, ignored java.lang.NullPointerException: Cannot invoke "org.apache.catalina.Context.bind(boolean, java.lang.ClassLoader)" because "this.context" is null at org.apache.catalina.core.AsyncContextImpl.fireOnComplete(AsyncContextImpl.java:101) at org.apache.coyote.AsyncStateMachine.asyncPostProcess(AsyncStateMachine.java:286) at org.apache.coyote.AbstractProcessor.asyncPostProcess(AbstractProcessor.java:197) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:78) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:894) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1740) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.base/java.lang.Thread.run(Thread.java:833) - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: stack traces from Tomcat 10.1.12
Hi Christopher, thank you for answering. Checking the thread id of the logs, all I can tell is that it looks these errors weren't coming from application-managed threads since they're in the shape of "http-nio-#port-exec-#number". There are application-managed threads but for doing async some specific pieces of the code (i.e. we don't use reactive code, the request itself is managed by Spring Boot). I've only seen two occurrences of those two stack traces so far, so it's not something that happens a lot and they happened at arbitrary times, definitely not at deployment nor shutdown. The app kept working as normal after this happened. Thanks, Tomás On Fri, Sep 29, 2023 at 1:04 PM Christopher Schultz wrote: > > Thomás, > > On 9/29/23 03:03, Tomás García wrote: > > I've noticed these stack traces happening in the same row with Tomcat > > 10.1.12, Java 17 and Spring Boot 3.1.3. I don't have a way to > > reproduce them unfortunately. I thought that it could be related to > > https://bz.apache.org/bugzilla/show_bug.cgi?id=67235 but not sure. > > Sharing them here in case it could be useful to pinpoint any issue in > > case these are not already fixed in current development branch of > > Tomcat or its latest version. > > Can you provide any more context? I don't see, for example, any > application code in these stack traces which means something has caused > Tomcat's own internal async state tracking to get confused about something. > > Are you using application-managed threads to handle your async requests? > Can you provide some sample code for how you use them? > > Do these errors happen at arbitrary times, or could they be happening > around application re-deployment, Tomcat shut-down, etc.? > > Anything else you could provide which would help? > > -chris > > > Stacktraces: > > logger org.apache.catalina.connector.CoyoteAdapter > > messageException while processing an asynchronous request > > > > java.lang.IllegalStateException: Calling [asyncComplete()] is not > > valid for a request with Async state [COMPLETING] > >at > > org.apache.coyote.AsyncStateMachine.asyncComplete(AsyncStateMachine.java:345) > >at > > org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:508) > >at org.apache.coyote.Request.action(Request.java:514) > >at > > org.apache.catalina.core.AsyncContextImpl.complete(AsyncContextImpl.java:91) > >at > > org.apache.catalina.core.AsyncContextImpl.setErrorState(AsyncContextImpl.java:427) > >at > > org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:155) > >at > > org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:243) > >at > > org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:57) > >at > > org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:894) > >at > > org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1740) > >at > > org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) > >at > > org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) > >at > > org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) > >at > > org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) > >at java.base/java.lang.Thread.run(Thread.java:833) > > > > logger org.apache.coyote.http11.Http11NioProtocol > > messageError reading request, ignored > > > > java.lang.NullPointerException: Cannot invoke > > "org.apache.catalina.Context.bind(boolean, java.lang.ClassLoader)" > > because "this.context" is null > >at > > org.apache.catalina.core.AsyncContextImpl.fireOnComplete(AsyncContextImpl.java:101) > >at > > org.apache.coyote.AsyncStateMachine.asyncPostProcess(AsyncStateMachine.java:286) > >at > > org.apache.coyote.AbstractProcessor.asyncPostProcess(AbstractProcessor.java:197) > >at > > org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:78) > >at > > org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:894) > >at > > org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1740) > >at > > org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) > >at > > org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) > >at > > org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) > >at > > org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) > >
Re: Migrating Tomcat 8/9 and a single webapp to Java 17 disconfigures Tomcat logs
Hi Christopher, Thanks for the suggestion, we do add some jars to Tomcat lib (mainly Prometheus, Hazelcast) I expanded every jar inside tomcat/lib and ran a find command. root@05ae85e03d7d:/# find ./ -type f -name logging.properties ./usr/local/tomcat/conf/logging.properties ./opt/java/openjdk/conf/logging.properties The only other logging.properties is the one from JDK. I tried changing its content just to see if that was what was being used, but it had no effect. So the issue still remains, but we have worked around it by configuring tomcat to use log4j2 as per this documentation: https://logging.apache.org/log4j/2.x/log4j-appserver.html With this and the log4j-jul bridge, all logs are now formatted correctly. > Em 29 de set. de 2023, à(s) 08:56, Christopher Schultz > escreveu: > > Alcides, > > On 9/28/23 14:55, Alcides Moraes wrote: >> Hello everyone, >> I’m new to the list even though I’ve been a Java web developer for many >> years, I’ve never had the need to post here, but this time I think I may >> have stumbled upon a bug, and nothing turns up online on this issue. >> We’re migrating our containerized legacy webapps from Java 8/11 to Java 17. >> They all ran on Tomcat 8.5, now we’re upgrading to 9. >> We customize a base image from tomcat:9.0.80-jdk17-temurin-focal. Amongst >> other things, we add a logging.properties to customize tomcat’s log format. >> This always worked well, but after our upgrade to Java 17, there’s a weird >> behavior that has stumped us. >> During Tomcat’s startup, the logs are formatted correctly as we specify in >> logging.properties. However, after a certain point in the logs, the logs >> revert to the “default” JUL/JULI format. >> Apart from this, everything works as expected. But we need the formatted >> logs because we parse them with LogStash and OpenSearch. >> Here’s an excerpt of the logs when this happens: >> local-corporativo-comum-1 | 2023-09-27T18:57:34.188 INFO >> [org.apache.coyote.http11.Http11NioProtocol] (thread-1) Initializing >> ProtocolHandler ["http-nio-8080"] >> local-corporativo-comum-1 | 2023-09-27T18:57:34.266 INFO >> [org.apache.catalina.startup.Catalina] (thread-1) Server initialization in >> [3419] milliseconds >> local-corporativo-comum-1 | 2023-09-27T18:57:34.606 INFO >> [com.hazelcast.config.UrlXmlConfig] (thread-1) Configuring Hazelcast from >> 'file:/usr/local/tomcat/conf/hazelcast-local.xml'. >> local-corporativo-comum-1 | 2023-09-27T18:57:36.775 INFO >> [org.apache.catalina.core.StandardService] (thread-1) Starting service >> [Catalina] >> local-corporativo-comum-1 | 2023-09-27T18:57:36.789 INFO >> [org.apache.catalina.core.StandardEngine] (thread-1) Starting Servlet >> engine: [Secure Web Server] >> local-corporativo-comum-1 | 2023-09-27T18:57:36.863 INFO >> [org.apache.catalina.startup.HostConfig] (thread-1) Diretório de instalação >> da aplicação web [/usr/local/tomcat/webapps/corporativo-comum] >> local-corporativo-comum-1 | 2023-09-27T18:57:52.647 INFO >> [br.leg.senado.util.tomcat.DataSourceFactory] (thread-1) Criando instância >> do datasource corporativo-comumDS >> local-corporativo-comum-1 | set. 27, 2023 6:57:55 PM >> br.leg.senado.util.tomcat.DataSourceFactory getObjectInstance >> local-corporativo-comum-1 | INFORMAÇÕES: Criando instância do datasource >> monitoraaplDS >> local-corporativo-comum-1 | set. 27, 2023 6:57:55 PM >> org.apache.catalina.core.ApplicationContext log >> local-corporativo-comum-1 | INFORMAÇÕES: 1 Spring >> WebApplicationInitializers detected on classpath >> local-corporativo-comum-1 | set. 27, 2023 6:57:55 PM >> org.apache.catalina.core.ApplicationContext log >> local-corporativo-comum-1 | INFORMAÇÕES: Initializing Spring root >> WebApplicationContext >> local-corporativo-comum-1 | 18:57:55.751 [main] INFO >> org.springframework.web.context.ContextLoader - Root WebApplicationContext: >> initialization started >> The red text is tomcat logging using the defaults (which localize log levels >> to our locale which is pt-br). >> I suspect that the point where this happens is when the webapp is being >> initialized. A webapp shouldn’t be able to interfere with Tomcat’s log >> behavior, right? >> The webapp does not use JUL, it uses logback, and it logs correctly during >> and after its startup. >> The logs you see @ 18:57:52 that says “Criando instância...” are of custom >> datasource resources specified in a context.xml file. >> They have a custom factory class, passed from a custom jar in tomcat's class >> path. >> This jar has worked and logged correctly since ever, we didn’t even >> recompile them to Java 17, we kept them as they were (Java 8). >> I’ve tried changing the way this component logs, by calling org.apache.juli >> instead of java.util.logging, removed all logging whatsoever, but nothing >> changes this behavior. >> Any suggestions on debugging this? If you need more info don’t hesitate to >> ask. >> Thanks in advance for any help
Best way to *programmatically* detect that all webapps are fully deployed and running?
On a tomcat server I have a number of REST services deployed as WARs. There are interdependencies and even applications on other servers that call them, so I really don't want to start calling services after starting Tomcat until every single webapp is fully up and running. Ideally, I would like to do it*programmatically*. QUESTIONS * Is there a REST, other kind of API that I can call or a library that I can use? * Is there a known best practice on how to accomplish what I am looking for? Perhaps a third party library that does the job? Things I know I can try, but none is an ideal solution: * Manually look at the logs. * Manually look at the Tomcat Application Management page. * Programmatically call the Tomcat Application Management page and scrape the information I need from it. * Scour through the code of the Tomcat Application Management page and replicate the pieces that I need, for example someone mentioned in a forum that I can look at org.apache.catalina.manager.ManagerServlet.isDeployed(String name) to find out whether a webapp has been deployed or not. Thanks, - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Migrating Tomcat 8/9 and a single webapp to Java 17 disconfigures Tomcat logs
Forgot to expand the webapps/WEB-INF/lib jars as well… root@8ad4f1dcd125:/usr/local/tomcat# find ./ -type f -name logging.properties ./conf/logging.properties ./webapps/corporativo-comum/WEB-INF/lib/org/springframework/boot/logging/java/logging.properties So there’s springboot's logging.properties. Should it really affect tomcat’s logging? > Em 29 de set. de 2023, à(s) 16:18, Alcides Moraes > escreveu: > > Hi Christopher, > > Thanks for the suggestion, we do add some jars to Tomcat lib (mainly > Prometheus, Hazelcast) > I expanded every jar inside tomcat/lib and ran a find command. > > root@05ae85e03d7d:/# find ./ -type f -name logging.properties > ./usr/local/tomcat/conf/logging.properties > ./opt/java/openjdk/conf/logging.properties > > The only other logging.properties is the one from JDK. I tried changing its > content just to see if that was what was being used, but it had no effect. > > So the issue still remains, but we have worked around it by configuring > tomcat to use log4j2 as per this documentation: > https://logging.apache.org/log4j/2.x/log4j-appserver.html > > With this and the log4j-jul bridge, all logs are now formatted correctly. > >> Em 29 de set. de 2023, à(s) 08:56, Christopher Schultz >> escreveu: >> >> Alcides, >> >> On 9/28/23 14:55, Alcides Moraes wrote: >>> Hello everyone, >>> I’m new to the list even though I’ve been a Java web developer for many >>> years, I’ve never had the need to post here, but this time I think I may >>> have stumbled upon a bug, and nothing turns up online on this issue. >>> We’re migrating our containerized legacy webapps from Java 8/11 to Java 17. >>> They all ran on Tomcat 8.5, now we’re upgrading to 9. >>> We customize a base image from tomcat:9.0.80-jdk17-temurin-focal. Amongst >>> other things, we add a logging.properties to customize tomcat’s log format. >>> This always worked well, but after our upgrade to Java 17, there’s a weird >>> behavior that has stumped us. >>> During Tomcat’s startup, the logs are formatted correctly as we specify in >>> logging.properties. However, after a certain point in the logs, the logs >>> revert to the “default” JUL/JULI format. >>> Apart from this, everything works as expected. But we need the formatted >>> logs because we parse them with LogStash and OpenSearch. >>> Here’s an excerpt of the logs when this happens: >>> local-corporativo-comum-1 | 2023-09-27T18:57:34.188 INFO >>> [org.apache.coyote.http11.Http11NioProtocol] (thread-1) Initializing >>> ProtocolHandler ["http-nio-8080"] >>> local-corporativo-comum-1 | 2023-09-27T18:57:34.266 INFO >>> [org.apache.catalina.startup.Catalina] (thread-1) Server initialization in >>> [3419] milliseconds >>> local-corporativo-comum-1 | 2023-09-27T18:57:34.606 INFO >>> [com.hazelcast.config.UrlXmlConfig] (thread-1) Configuring Hazelcast from >>> 'file:/usr/local/tomcat/conf/hazelcast-local.xml'. >>> local-corporativo-comum-1 | 2023-09-27T18:57:36.775 INFO >>> [org.apache.catalina.core.StandardService] (thread-1) Starting service >>> [Catalina] >>> local-corporativo-comum-1 | 2023-09-27T18:57:36.789 INFO >>> [org.apache.catalina.core.StandardEngine] (thread-1) Starting Servlet >>> engine: [Secure Web Server] >>> local-corporativo-comum-1 | 2023-09-27T18:57:36.863 INFO >>> [org.apache.catalina.startup.HostConfig] (thread-1) Diretório de instalação >>> da aplicação web [/usr/local/tomcat/webapps/corporativo-comum] >>> local-corporativo-comum-1 | 2023-09-27T18:57:52.647 INFO >>> [br.leg.senado.util.tomcat.DataSourceFactory] (thread-1) Criando instância >>> do datasource corporativo-comumDS >>> local-corporativo-comum-1 | set. 27, 2023 6:57:55 PM >>> br.leg.senado.util.tomcat.DataSourceFactory getObjectInstance >>> local-corporativo-comum-1 | INFORMAÇÕES: Criando instância do datasource >>> monitoraaplDS >>> local-corporativo-comum-1 | set. 27, 2023 6:57:55 PM >>> org.apache.catalina.core.ApplicationContext log >>> local-corporativo-comum-1 | INFORMAÇÕES: 1 Spring >>> WebApplicationInitializers detected on classpath >>> local-corporativo-comum-1 | set. 27, 2023 6:57:55 PM >>> org.apache.catalina.core.ApplicationContext log >>> local-corporativo-comum-1 | INFORMAÇÕES: Initializing Spring root >>> WebApplicationContext >>> local-corporativo-comum-1 | 18:57:55.751 [main] INFO >>> org.springframework.web.context.ContextLoader - Root WebApplicationContext: >>> initialization started >>> The red text is tomcat logging using the defaults (which localize log >>> levels to our locale which is pt-br). >>> I suspect that the point where this happens is when the webapp is being >>> initialized. A webapp shouldn’t be able to interfere with Tomcat’s log >>> behavior, right? >>> The webapp does not use JUL, it uses logback, and it logs correctly during >>> and after its startup. >>> The logs you see @ 18:57:52 that says “Criando instância...” are of custom >>> datasource resources specified in a context.xml file. >>> They have
