log4j syslogappender stack trace output not on the same line

Question

I am trying to get centralised logging working with log4j and rsyslog.

What I have so far

Solr running inside tomcat6 on RHEL6, using the following log4j and sl4j libs

# lsof -u tomcat | grep log4j
java    14503 tomcat  mem    REG              253,0      9711    10208 /usr/share/java/tomcat6/slf4j-log4j12-1.6.6.jar
java    14503 tomcat  mem    REG              253,0    481535    10209 /usr/share/java/tomcat6/log4j-1.2.16.jar
java    14503 tomcat  mem    REG              253,0    378088  1065276 /usr/share/java/log4j-1.2.14.jar
java    14503 tomcat   20r   REG              253,0    378088  1065276 /usr/share/java/log4j-1.2.14.jar
java    14503 tomcat   21r   REG              253,0    481535    10209 /usr/share/java/tomcat6/log4j-1.2.16.jar
java    14503 tomcat   35r   REG              253,0      9711    10208 /usr/share/java/tomcat6/slf4j-log4j12-1.6.6.jar
# 

Solr is using the following log4j.properties file (via -Dlog4j.configuration=file:///opt/solr/lib/log4j.properties)

#  Logging level
log4j.rootLogger=INFO, file, CONSOLE, SYSLOG

log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender

log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=%-4r [%t] %-5p %c %x \u2013 %m%n

#- size rotation with log cleanup.
log4j.appender.file=org.apache.log4j.RollingFileAppender
log4j.appender.file.MaxFileSize=4MB
log4j.appender.file.MaxBackupIndex=9

#- File to log to and log format
log4j.appender.file.File=/var/log/tomcat6/solr.log
log4j.appender.file.layout=org.apache.log4j.PatternLayout
log4j.appender.file.layout.ConversionPattern=%-5p - %d{yyyy-MM-dd HH:mm:ss.SSS}; %C; %m\n

log4j.logger.org.apache.zookeeper=WARN
log4j.logger.org.apache.hadoop=WARN

# set to INFO to enable infostream log messages
log4j.logger.org.apache.solr.update.LoggingInfoStream=OFF

#- Local syslog server
log4j.appender.SYSLOG=org.apache.log4j.net.SyslogAppender
log4j.appender.SYSLOG.syslogHost=localhost
log4j.appender.SYSLOG.facility=LOCAL1
log4j.appender.SYSLOG.layout=org.apache.log4j.PatternLayout
log4j.appender.SYSLOG.layout.ConversionPattern=${sysloghostname} %-4r [%t] java %-5p %c %x %m%n
log4j.appender.SYSLOG.Header=true

On the same server I have rsyslog running and accepting log messages from log4j.

# rpmquery -a | grep syslog
rsyslog-5.8.10-7.el6_4.x86_64
# 

rsyslog config

# #### MODULES ####
$MaxMessageSize 32k
$ModLoad imuxsock # provides support for local system logging (e.g. via logger command)
$ModLoad imklog   # provides kernel logging support (previously done by rklogd)
$ModLoad imfile   # provides file monitoring support
#
$ModLoad imudp.so
$UDPServerRun 514
$WorkDirectory /var/lib/rsyslog # where to place spool files
# #### GLOBAL DIRECTIVES ####
# # Use default timestamp format
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$IncludeConfig /etc/rsyslog.d/*.conf
$ActionQueueType LinkedList   # run asynchronously
$ActionQueueFileName fwdRule1 # unique name prefix for spool files
$ActionQueueMaxDiskSpace 1g   # 1gb space limit (use as much as possible)
$ActionQueueSaveOnShutdown on # save messages to disk on shutdown
$ActionResumeRetryCount -1    # infinite retries if host is down

$ActionSendStreamDriverMode 0 # require TLS for the connection
$ActionSendStreamDriverAuthMode anon # chain and server are verified
#local1.*;*.* @@(o)XXXXXXXX:5544
local1.*                                                /var/log/remote.log
# # The authpriv file has restricted access.
authpriv.*                                              /var/log/secure
# # Log all the mail messages in one place.
mail.*                                                  -/var/log/maillog
# # Log cron stuff
cron.*                                                  /var/log/cron
# # Everybody gets emergency messages
*.emerg                                                 *
# # Save news errors of level crit and higher in a special file.
uucp,news.crit                                          /var/log/spooler
# # Save boot messages also to boot.log
local7.*                                                /var/log/boot.log

I am catching local1 messages from Solr's logj4 and redirecting them to /var/log/remote.log Everything works as expected. Sample INFO message

Oct 31 13:57:08 hostname.here 3431839 [http-8080-10] java INFO  org.apache.solr.core.SolrCore  [collection1] webapp=/solr path=/select params={indent=true&q=*:*&wt=json&rows=1} hits=42917 status=0 QTime=1

And stack traces are on the same line as the ERROR message

Oct 31 12:27:17 hostname.here 157666248 [http-8080-7] java ERROR org.apache.solr.core.SolrCore  org.apache.solr.common.SolrException: undefined field *#012#011at org.apache.solr.schema.IndexSchema.getDynamicFieldType(IndexSchema.java:1223)#012... Cut for brevity....#011at java.lang.Thread.run(Thread.java:724)#012

Note #012 as line ending and #011 tab.

Using this setup I can ship the logs to remote rsyslog server over TCP and pipe them into fluentd/elaticsearch/kibana etc... everything works as expected.

The problem I am now trying to get another webapp running inside the same tomcat container to log as above, everything works as expected apart from stack traces, each line of a stack trace ends up on a separate line (separate syslog message)

Oct 31 12:54:47  hostname.here 4909 [main] java ERROR org.hibernate.tool.hbm2ddl.SchemaUpdate  could not get database metadata
Oct 31 12:54:47 hostname.here org.apache.commons.dbcp.SQLNestedException: Cannot create PoolableConnectionFactory (Communications link failure
Oct 31 12:54:47 hostname.here 
Oct 31 12:54:47 hostname.here The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.)

The webapp ships with it's own log4j libs and log4j.xml config. Libs are of the same version as those used by solr.

log4j.xml file for this app

 <appender name="SYSLOG" class="org.apache.log4j.net.SyslogAppender">
                <param name="SyslogHost" value="localhost" />
                <param name="Facility" value="LOCAL1" />
                <param name="Header" value="false" />
                <property name="facilityPrinting" value="false"/>
                <param name="Threshold" value="DEBUG" />
                <layout class="org.apache.log4j.PatternLayout">
                <param name="ConversionPattern"
                      value="%-4r [%t] java %-5p %c %x %m%n"/>
                </layout>
                </appender>

I would like to see stack traces from the new application to appear on the same line just like with Solr.

Does anyone know if this is a log4j config issue?

Many thanks.

Answer 1

I've been working on something similar lately (in fact, I have this question open presently you may be able to help with).

This is probably not a very good answer, but it's more information than I can fit in a comment so here you go (I hope some of it is new to you). The rsyslog imfile rsyslog documentation has this section:

ReadMode [mode]

This mode should defined when having multiline messages. The value can range from 0-2 and determines the multiline detection method.
0 (default) - line based (Each line is a new message)
1 - paragraph (There is a blank line between log messages)
2 - indented (New log messages start at the beginning of a line. If a line starts with a space it is part of the log message before it)

The imudp rsyslog docs have no such configuration option. My guess is that the UDP input module doesn't support multiline logging. Thus, each line of the stack trace is sent out as a separate log entry.

Do you have any configuration files in /etc/rsyslog.d? There may be more information in there.