Fix JUL ECS logging no longer converting plain text logs to JSON

[jackshirazi]

Describe the bug

Setting the config in tomcat for java.util.logging to use a org.apache.juli.AsyncFileHandler as a handler and in turn setting the formatter for that to co.elastic.logging.jul.EcsFormatter should result in JSON format logs and did in 1.18.1 but stopped working in 1.19.0. From 1.19.0+ the log lines no longer convert to JSON format (and so remain in the plain text format).

Steps to reproduce

1. setup tomcat to be able to run
2. add or modify a setenv.sh in the tomcat bin directory to add a ecs-logging-core and jul-ecs-formatter to the classpath, eg
   CLASSPATH=/SOMEPATH0/jul-ecs-formatter-1.3.2.jar:/SOMEPATH0/ecs-logging-core-1.3.2.jar
   and add the agent startup flag, together with specifying the apm config file, eg
   export CATALINA_OPTS="-javaagent:/SOMEPATH0/elastic-apm-agent-1.19.0.jar -Delastic.apm.config_file=/SOMEPATH1/FNAME1.properties $CATALINA_OPTS"
   Note the config file can be empty and doesn't need to specify pointing at a valid apm server, though setting the agent log file is a good idea with the log_file property, eg
   log_file=/SOMEPATH2/FNAME2.log
   Note you need the 3 jars listed to be present and in the path you specify, SOMEPATH0 is just an example
3. In the tomcat logging properties file (usually logging.properties in the tomcat conf directory set the handler to AsyncFileHandler and set it's formatter to co.elastic.logging.jul.EcsFormatter, eg like the example below
4. Start and stop tomcat, and check the format of the entries in the log files specified in the logging.properties file (no need to execute any requests, the startup logging is sufficient). The log entries should be plain text
5. Change the agent to the prior version 1.18.1 and repeat, the log entries should be in JSON format

Example logging properties entries:

handlers = 1catalina.org.apache.juli.AsyncFileHandler, 2localhost.org.apache.juli.AsyncFileHandler, 3manager.org.apache.juli.AsyncFileHandler

.handlers = 1catalina.org.apache.juli.AsyncFileHandler

############################################################
# Handler specific properties.
# Describes specific configuration info for Handlers.
############################################################

1catalina.org.apache.juli.AsyncFileHandler.level = FINE
1catalina.org.apache.juli.AsyncFileHandler.directory = /var/log/tomcat
1catalina.org.apache.juli.AsyncFileHandler.maxDays = 15
1catalina.org.apache.juli.AsyncFileHandler.prefix = catalina.
1catalina.org.apache.juli.AsyncFileHandler.suffix = .json
1catalina.org.apache.juli.AsyncFileHandler.encoding = UTF-8
1catalina.org.apache.juli.AsyncFileHandler.formatter = co.elastic.logging.jul.EcsFormatter

2localhost.org.apache.juli.AsyncFileHandler.level = FINE
2localhost.org.apache.juli.AsyncFileHandler.directory = /var/log/tomcat
2localhost.org.apache.juli.AsyncFileHandler.maxDays = 15
2localhost.org.apache.juli.AsyncFileHandler.prefix = localhost.
2localhost.org.apache.juli.AsyncFileHandler.suffix = .json
2localhost.org.apache.juli.AsyncFileHandler.encoding = UTF-8
2localhost.org.apache.juli.AsyncFileHandler.formatter = co.elastic.logging.jul.EcsFormatter

3manager.org.apache.juli.AsyncFileHandler.level = FINE
3manager.org.apache.juli.AsyncFileHandler.directory = /var/log/tomcat
3manager.org.apache.juli.AsyncFileHandler.maxDays = 15
3manager.org.apache.juli.AsyncFileHandler.prefix = manager.
3manager.org.apache.juli.AsyncFileHandler.suffix = .json
3manager.org.apache.juli.AsyncFileHandler.encoding = UTF-8
3manager.org.apache.juli.AsyncFileHandler.formatter = co.elastic.logging.jul.EcsFormatter

#java.util.logging.ConsoleHandler.level = FINE
#java.util.logging.ConsoleHandler.formatter = co.elastic.logging.jul.EcsFormatter
co.elastic.logging.jul.EcsFormatter.serviceName=tomcat-default
#java.util.logging.ConsoleHandler.encoding = UTF-8


############################################################
# Facility specific properties.
# Provides extra control for each logger.
############################################################

org.apache.catalina.core.ContainerBase.[Catalina].[localhost].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].handlers = 2localhost.org.apache.juli.AsyncFileHandler

org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager].level = INFO
org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/manager].handlers = 3manager.org.apache.juli.AsyncFileHandler

Expected behavior

The logs specified in the logging.properties should hold JSON format log lines
eg
{"@timestamp":"2022-01-06T21:42:34.247Z", "log.level": "INFO", "message":"ContextListener: contextInitialized()", "ecs.version": "1.2.0","service.name":"tomcat-default","event.dataset":"tomcat-default","process.thread.id":1,"log.logger":"org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/examples]"}
and not plain text, eg
06-Jan-2022 20:07:59.725 INFO [main] org.apache.catalina.core.ApplicationContext.log ContextListener: contextInitialized()

[eyalkoren]

@jackshirazi I don't know what's causing this and so I can't see how #2428 may affect that, but worth checking whether it's still the same with this PR's latest snapshot before diving into investigation.

[jackshirazi]

Confirmed that the snapshot fixes the issue. Checked with

• 1.29.0 - has the issue
• 1.29.0 with 1 second agent start delay - works around the issue
• snapshot with no agent startup delay - has no issue

[jackshirazi]

fixed in 1.30.0