spotify/logging-java

Ugly exceptions being written into log dirs

varjoranta opened this issue · 8 comments

I'm not sure whether this issue has been solved already, but I can see some folders with exception names being created into my syslogng controlled log dir.

The syslogng config looks something like follows for the destination:
destination df_blah_local_level {file("/var/log/blah/$PROGRAM/${LEVEL}.log");};

And confirmed that when a non-main thread throws an uncatched exception, it will create folders like:
drwxr-xr-x 2 root root 4096 Mar 18 13:57 ?com.fasterxml.jackson.databind.exc.UnrecognizedPropertyException

And that one above is a folder listed in the /var/log/blah/ directory.

Is this issue in syslog-ng configuration or in logging-java, or somewhere else?

Generally this is an issue when sending multi-line log messages to syslog on a stream transport such as tcp/unix sockets or stdio. The syslog daemon typically then uses newlines as a log message delimiter, which breaks for multi-line messages.

The syslog appender as set up by logging-java should be escaping newlines in stack traces. Sounds like that's not happening in your case though. How are you invoking LoggingConfigurator? I.e., are you calling LoggingConfigurator.configureSyslogDefaults(), or some other configuration method?

Here is the used logback configuration:

<configuration scan="true" scanPeriod="2 seconds">
    <appender name="syslog" class="com.spotify.logging.logback.MillisecondPrecisionSyslogAppender">
        <syslogHost>localhost</syslogHost>
        <facility>local0</facility>
        <suffixPattern>%property{ident}[%property{pid}]: %-5level [%thread] %logger{0} - %msg</suffixPattern>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>DEBUG</level>
        </filter>
    </appender>

    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%-4relative [%thread] %-5level %logger{35} - %msg %n</pattern>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>DEBUG</level>
        </filter>
    </appender>

    <root level="INFO">
        <appender-ref ref="syslog" />
    </root>
</configuration>

Dano was able to repeat an issue with the following code, i.e. it outputs exceptions into stdout or stderr instead of syslog.
https://github.com/spotify/logging-java/blob/dano/test/src/main/java/ExceptionSpammer.java

So I manage to reproduce an unexpected behavior where an uncaught exception gets printed on stdout/err by doing mvn exec:java -Dexec.mainClass=ExceptionSpammer.

However, if I shade the jar and run it like java -jar target/logging-2.1.2-SNAPSHOT-shaded.jar, then all exception logging end up in syslog.

There might be some race in how the loggers/appenders are being set up.

Turns out that the original issue was likely due to the application in question explicitly writing stack traces to stderr using Throwable.printStackTrace().

The mvn exec:java -Dexec.mainClass=ExceptionSpammer behaviour that I was seeing is due to the maven exec plugin configuring an UncaughtExceptionHandler for the ThreadGroup, which takes precedence over the default UncaughtExceptionHandler that we set using Thread.setDefaultUncaughtExceptionHandler(UncaughtExceptionHandler). Red herring.

@varjoranta There's little logging-java can do to prevent applications from printing to stdout/err. So this should probably be pursued as an issue with supervision and/or our syslog-ng setup.

If you don't mind I will close this issue.

We can close this issue, as it can be fixed by removing the exception.printStackTrace() form the code.