akka, spray, and log4j2 not logging right

Question

I am scaffolding a new application in Akka, Spray, and Log4j2. I have most of the major systems working in "hello world" type mode, but I'm having a hard time getting the logging to work as I want and I can't tell if this is a log4j2 issue, an Akka/Spray issue, or a retarded me issue.

First, my Akka config file

akka {
    loggers = ["akka.event.slf4j.Slf4jLogger"]
    loglevel = DEBUG
    log-config-on-start = on

    actor{
        debug {
              receive = on
              autoreceive = on
              lifecycle = on
              fsm = on
              event-stream = on
              unhandled = on
              router-misconfiguration = on
            }
    }
}

Now, if I comment out the loggers line and run the app in IntelliJ, its perfect in the console. I get everything I want, I get very verbose and helpful logs, I get the config settings, I see the transactions coming in and going out, I'm a very happy person. The problem occurs when I try to pipe it thru Log4j2.

Now the reason I want to do this is in the not too distant future, i'm going to be pumping all logs to a Cassandra cluster for mapreduce work.

So I uncomment the slf4j line in the config file above, add slf4j, log4j2 and log4j2's log4j-slf4j-impl in the classpath and log4j activates, reads the config file, creates the log file, logs to the console the initializing of the appenders and the debug info, and thats it. nothing else comes out. not one blessed thing. nada.

here's my log4j2.xml file

<?xml version="1.0" encoding="UTF-8"?>
<configuration status="DEBUG">
    <appenders>
        <Console name="CONSOLE" target="SYSTEM_OUT">
            <PatternLayout pattern="%-5p %c{2} - %m%n" />
        </Console>
        <RollingRandomAccessFile name="logFileOutput" fileName="logs/wisdomOutput.log"
                     filePattern="logs/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-%i.log.gz">
            <PatternLayout>
                <pattern>%d %p %C [%t] %m%n</pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="50 MB"/>
            </Policies>
            <DefaultRolloverStrategy max="20"/>
        </RollingRandomAccessFile>
    </appenders>
    <loggers>
        <!-- if you want to dump different packages to different files, here's where you do it
            <logger name="com.onuspride" level="DEBUG" additivity="false">
            <appender-ref ref="logFileOutput"/>
        </logger>-->
        <root>
            <appender-ref ref="CONSOLE"/>
            <appender-ref ref="logFileOutput"/>
        </root>
    </loggers>
</configuration>

I don't know if I'm dealing with a bug in log4j2, or if my configuration file is wrong, or what.

Here is my console output when my logging is activated

/usr/lib/jvm/java-7-oracle/bin/java -Didea.launcher.port=7533 -Didea.launcher.bin.path=/home/willie/apps/intellij13/bin -Dfile.encoding=UTF-8 -classpath /usr/lib/jvm/java-7-oracle/jre/lib/jfr.jar:/usr/lib/jvm/java-7-oracle/jre/lib/javaws.jar:/usr/lib/jvm/java-7-oracle/jre/lib/jsse.jar:/usr/lib/jvm/java-7-oracle/jre/lib/jfxrt.jar:/usr/lib/jvm/java-7-oracle/jre/lib/deploy.jar:/usr/lib/jvm/java-7-oracle/jre/lib/rt.jar:/usr/lib/jvm/java-7-oracle/jre/lib/jce.jar:/usr/lib/jvm/java-7-oracle/jre/lib/resources.jar:/usr/lib/jvm/java-7-oracle/jre/lib/plugin.jar:/usr/lib/jvm/java-7-oracle/jre/lib/management-agent.jar:/usr/lib/jvm/java-7-oracle/jre/lib/charsets.jar:/usr/lib/jvm/java-7-oracle/jre/lib/ext/zipfs.jar:/usr/lib/jvm/java-7-oracle/jre/lib/ext/dnsns.jar:/usr/lib/jvm/java-7-oracle/jre/lib/ext/sunec.jar:/usr/lib/jvm/java-7-oracle/jre/lib/ext/sunpkcs11.jar:/usr/lib/jvm/java-7-oracle/jre/lib/ext/localedata.jar:/usr/lib/jvm/java-7-oracle/jre/lib/ext/sunjce_provider.jar:/home/willie/code/onus/collective/build/production/wisdom:/home/willie/.gradle/caches/modules-2/files-2.1/org.scala-lang/scala-reflect/2.10.0/10ec1256a6e875e886fec050edb0669166912d0d/scala-reflect-2.10.0.jar:/home/willie/.gradle/caches/modules-2/files-2.1/io.spray/spray-routing/1.2.0/955690e1d6b0d92f06da4b53a185a0d59615e1c6/spray-routing-1.2.0.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.json4s/json4s-ast_2.10/3.2.6/e52c46c51f75a7536c3ffedefdbdc331ffaecbdd/json4s-ast_2.10-3.2.6.jar:/home/willie/.gradle/caches/modules-2/files-2.1/io.spray/spray-http/1.2.0/ba24112e069e61224255f6c3cf85727767351fcc/spray-http-1.2.0.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.json4s/json4s-core_2.10/3.2.6/c89c64b04fec958fc57a271bc741dfde759d8ffc/json4s-core_2.10-3.2.6.jar:/home/willie/.gradle/caches/modules-2/files-2.1/com.thoughtworks.paranamer/paranamer/2.6/52c3c8d8876440d714e23036eb87bcc4244d9aa5/paranamer-2.6.jar:/home/willie/.gradle/caches/modules-2/files-2.1/io.spray/spray-util/1.2.0/efea073f15b79a3f62f1f16b22cfcad9a2119439/spray-util-1.2.0.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.json4s/json4s-native_2.10/3.2.6/3728a03373e3eac2354ea0cc855fef71fe97d82e/json4s-native_2.10-3.2.6.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.scala-lang/scala-compiler/2.10.0/fec8066cd2b4f8dc7ff7ba7a8e0a792939d9f9a/scala-compiler-2.10.0.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.jvnet.mimepull/mimepull/1.9.3/c55096ff89a27e22c2e081371d0570ac19cc6788/mimepull-1.9.3.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.parboiled/parboiled-scala_2.10/1.1.6/bc93b215151f7dc42653f3eb0243b3130a7e1e11/parboiled-scala_2.10-1.1.6.jar:/home/willie/.gradle/caches/modules-2/files-2.1/com.chuusai/shapeless_2.10/1.2.4/2f41ccc19eb4d38ae5ef907ce7469003e0253dc5/shapeless_2.10-1.2.4.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.parboiled/parboiled-core/1.1.6/11bd0c34fc6ac3c3cbf440ab8180cc6422c044e9/parboiled-core-1.1.6.jar:/home/willie/.gradle/caches/modules-2/files-2.1/io.spray/spray-httpx/1.2.0/328e8d28cd3fcd7a7aea6467048a17577d427272/spray-httpx-1.2.0.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.scala-lang/scalap/2.10.0/ab42ae21d1fd7311b367fe3d7f33343f2e4bff6b/scalap-2.10.0.jar:/home/willie/code/onus/collective/build/production/inclusive:/home/willie/.gradle/caches/modules-2/files-2.1/org.apache.commons/commons-lang3/3.1/905075e6c80f206bbe6cf1e809d2caa69f420c76/commons-lang3-3.1.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.springframework.security/spring-security-web/3.1.4.RELEASE/56d52794df838d0bc3ccbc149a62ea019946f82a/spring-security-web-3.1.4.RELEASE.jar:/home/willie/.gradle/caches/modules-2/files-2.1/com.fasterxml.jackson.core/jackson-annotations/2.3.0/f5e853a20b60758922453d56f9ae1e64af5cb3da/jackson-annotations-2.3.0.jar:/home/willie/.gradle/caches/modules-2/files-2.1/commons-logging/commons-logging/1.1.1/5043bfebc3db072ed80fbd362e7caf00e885d8ae/commons-logging-1.1.1.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.springframework/spring-jdbc/3.0.7.RELEASE/c53d9bf4e6a6a6cf49c7d7630e612042364295a1/spring-jdbc-3.0.7.RELEASE.jar:/home/willie/.m2/repository/org/springframework/social/spring-social-security/1.1.0.M4/spring-social-security-1.1.0.M4.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.springframework/spring-webmvc/3.2.3.RELEASE/6d6d1b53c53dbefd0d8c15f2d5c194ced1f8d53c/spring-webmvc-3.2.3.RELEASE.jar:/home/willie/.m2/repository/org/springframework/social/spring-social-web/1.1.0.M4/spring-social-web-1.1.0.M4.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.springframework/spring-core/3.2.3.RELEASE/accdd65db57e79e49f2af037bb76f5a55a580f00/spring-core-3.2.3.RELEASE.jar:/home/willie/.gradle/caches/modules-2/files-2.1/aopalliance/aopalliance/1.0/235ba8b489512805ac13a8f9ea77a1ca5ebe3e8/aopalliance-1.0.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.springframework.security/spring-security-core/3.1.4.RELEASE/41af4a10d7e31722bd8ef2c101f60afb6c24e04b/spring-security-core-3.1.4.RELEASE.jar:/home/willie/.gradle/caches/modules-2/files-2.1/javax.inject/javax.inject/1/6975da39a7040257bd51d21a231b76c915872d38/javax.inject-1.jar:/home/willie/.m2/repository/org/springframework/social/spring-social-core/1.1.0.M4/spring-social-core-1.1.0.M4.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.springframework/spring-beans/3.2.3.RELEASE/a48eb92ef51e0aed7d23dcaa54225b8f24808db4/spring-beans-3.2.3.RELEASE.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.springframework/spring-expression/3.2.3.RELEASE/51e4c94a79892c0a2d15c5efda8c5b336ebf5c37/spring-expression-3.2.3.RELEASE.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.springframework/spring-web/3.2.3.RELEASE/833c5e9a60f82209a3f669a5026dfa8de57c1df3/spring-web-3.2.3.RELEASE.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.springframework/spring-context/3.2.3.RELEASE/12ad5920647556704f79cc579d4e133430741c5/spring-context-3.2.3.RELEASE.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.springframework/spring-aop/3.2.3.RELEASE/a70bec95e45a29cad126d250699d0ed0fedfe28a/spring-aop-3.2.3.RELEASE.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.springframework/spring-tx/3.0.7.RELEASE/c340bf8606f6bf235bc1277d25315df1abe51c31/spring-tx-3.0.7.RELEASE.jar:/home/willie/.gradle/caches/modules-2/files-2.1/io.spray/spray-can/1.2.0/4a3ec8def45e7f567739fe15a6537f57316612bf/spray-can-1.2.0.jar:/home/willie/.gradle/caches/modules-2/files-2.1/io.spray/spray-io/1.2.0/35c2866c4c7ac7f9b4ee2c06df18075a5bb8c55b/spray-io-1.2.0.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.apache.logging.log4j/log4j-api/2.0-beta9/1dd66e68cccd907880229f9e2de1314bd13ff785/log4j-api-2.0-beta9.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.apache.logging.log4j/log4j-core/2.0-beta9/678861ba1b2e1fccb594bb0ca03114bb05da9695/log4j-core-2.0-beta9.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.scala-lang/scala-library/2.10.3/21d99cee3d3e478255ef9fcc90b571fb2ab074fc/scala-library-2.10.3.jar:/home/willie/.gradle/caches/modules-2/files-2.1/com.typesafe/config/1.0.2/a0bca82c39f23f75e3afccd6e12840eeabaea123/config-1.0.2.jar:/home/willie/.gradle/caches/modules-2/files-2.1/com.typesafe.akka/akka-actor_2.10/2.2.3/3a74ea5a7ec2a23fa22077c4debebf96f015dc73/akka-actor_2.10-2.2.3.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.slf4j/slf4j-api/1.7.5/6b262da268f8ad9eff941b25503a9198f0a0ac93/slf4j-api-1.7.5.jar:/home/willie/.gradle/caches/modules-2/files-2.1/com.typesafe.akka/akka-slf4j_2.10/2.2.3/616c79a2d66ebd136bf0a4e5902bcd1e74dd4cb1/akka-slf4j_2.10-2.2.3.jar:/home/willie/.gradle/caches/modules-2/files-2.1/org.apache.logging.log4j/log4j-slf4j-impl/2.0-beta9/e970fc3c10144a521d691db4ac38027cc1935b74/log4j-slf4j-impl-2.0-beta9.jar:/home/willie/.gradle/caches/modules-2/files-2.1/com.lmax/disruptor/3.2.0/ac62995678dd4b906e85b26354aa2ebfda130c32/disruptor-3.2.0.jar:/home/willie/apps/intellij13/lib/idea_rt.jar com.intellij.rt.execution.application.AppMain com.onuspride.wisdom.Boot
2014-01-10 17:42:36,673 DEBUG Generated plugins in 0.000064883 seconds
2014-01-10 17:42:36,719 DEBUG Calling createLayout on class org.apache.logging.log4j.core.layout.PatternLayout for element PatternLayout with params(pattern="%-5p %c{2} - %m%n", Configuration(/home/willie/code/onus/collective/build/production/wisdom/log4j2.xml), null, charset="null", alwaysWriteExceptions="null")
2014-01-10 17:42:36,721 DEBUG Generated plugins in 0.000061321 seconds
2014-01-10 17:42:36,727 DEBUG Calling createAppender on class org.apache.logging.log4j.core.appender.ConsoleAppender for element Console with params(PatternLayout(%-5p %c{2} - %m%n), null, target="SYSTEM_OUT", name="CONSOLE", follow="null", ignoreExceptions="null")
2014-01-10 17:42:36,729 DEBUG Calling createLayout on class org.apache.logging.log4j.core.layout.PatternLayout for element PatternLayout with params(pattern="%d %p %C [%t] %m%n", Configuration(/home/willie/code/onus/collective/build/production/wisdom/log4j2.xml), null, charset="null", alwaysWriteExceptions="null")
2014-01-10 17:42:36,732 DEBUG Calling createPolicy on class org.apache.logging.log4j.core.appender.rolling.TimeBasedTriggeringPolicy for element TimeBasedTriggeringPolicy with params(interval="null", modulate="null")
2014-01-10 17:42:36,735 DEBUG Calling createPolicy on class org.apache.logging.log4j.core.appender.rolling.SizeBasedTriggeringPolicy for element SizeBasedTriggeringPolicy with params(size="50 MB")
2014-01-10 17:42:36,743 DEBUG Calling createPolicy on class org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy for element Policies with params(Policies={TimeBasedTriggeringPolicy, SizeBasedTriggeringPolicy(size=52428800)})
2014-01-10 17:42:36,748 DEBUG Calling createStrategy on class org.apache.logging.log4j.core.appender.rolling.DefaultRolloverStrategy for element DefaultRolloverStrategy with params(max="20", min="null", fileIndex="null", compressionLevel="null", Configuration(/home/willie/code/onus/collective/build/production/wisdom/log4j2.xml))
2014-01-10 17:42:36,754 DEBUG Calling createAppender on class org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender for element RollingRandomAccessFile with params(fileName="logs/wisdomOutput.log", filePattern="logs/${date:yyyy-MM}/app-%d{MM-dd-yyyy}-%i.log.gz", append="null", name="logFileOutput", immediateFlush="null", Policies(CompositeTriggeringPolicy{TimeBasedTriggeringPolicy, SizeBasedTriggeringPolicy(size=52428800)}), DefaultRolloverStrategy(DefaultRolloverStrategy(min=1, max=20)), PatternLayout(%d %p %C [%t] %m%n), null, ignoreExceptions="null", advertise="null", advertiseURI="null", Configuration(/home/willie/code/onus/collective/build/production/wisdom/log4j2.xml))
2014-01-10 17:42:36,763 DEBUG Starting RollingRandomAccessFileManager logs/wisdomOutput.log
2014-01-10 17:42:36,767 DEBUG Generated plugins in 0.000057060 seconds
2014-01-10 17:42:36,772 DEBUG Calling createAppenders on class org.apache.logging.log4j.core.config.plugins.AppendersPlugin for element appenders with params(Appenders={CONSOLE, logFileOutput})
2014-01-10 17:42:36,773 DEBUG Generated plugins in 0.000052311 seconds
2014-01-10 17:42:36,777 DEBUG Calling createAppenderRef on class org.apache.logging.log4j.core.config.AppenderRef for element appender-ref with params(ref="CONSOLE", level="null", null)
2014-01-10 17:42:36,778 DEBUG Calling createAppenderRef on class org.apache.logging.log4j.core.config.AppenderRef for element appender-ref with params(ref="logFileOutput", level="null", null)
2014-01-10 17:42:36,783 DEBUG Calling createLogger on class org.apache.logging.log4j.core.config.LoggerConfig$RootLogger for element root with params(additivity="null", level="null", includeLocation="null", AppenderRef={CONSOLE, logFileOutput}, Properties={}, Configuration(/home/willie/code/onus/collective/build/production/wisdom/log4j2.xml), null)
2014-01-10 17:42:36,787 DEBUG Calling createLoggers on class org.apache.logging.log4j.core.config.plugins.LoggersPlugin for element loggers with params(Loggers={root})
2014-01-10 17:42:36,799 DEBUG Reconfiguration completed
2014-01-10 17:42:36,808 DEBUG Using default SystemClock for timestamps
2014-01-10 17:42:36,815 DEBUG property AsyncLogger.WaitStrategy=null
2014-01-10 17:42:36,815 DEBUG disruptor event handler uses SleepingWaitStrategy
2014-01-10 17:42:37,045 DEBUG No AsyncLogger.ExceptionHandler specified
2014-01-10 17:42:37,058 DEBUG Starting AsyncLogger disruptor with ringbuffer size 262144...

I guess my problem is I can't figure out how to channel stdout from Akka, thru log4j2 to be formatted, and then written to a file. For the time being I really don't want to be any more complex than that.

What is wrong with my setup? Why isn't this working?

Answer 1

figure it out. here's my config

<?xml version="1.0" encoding="UTF-8"?>
<configuration status="debug">
    <appenders>
        <!--<Console name="CONSOLE" target="SYSTEM_OUT">
            <PatternLayout pattern="%-5p %c{2} - %m%n" />
        </Console>-->
        <RollingRandomAccessFile name="logFileOutput" fileName="logs/wisdomOutput.log"
                     filePattern="logs/$${date:yyyy-MM}/app-%d{MM-dd-yyyy}-%i.log.gz">
            <PatternLayout>
                <pattern>%d %p %C [%t] %m%n</pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="50 MB"/>
            </Policies>
            <DefaultRolloverStrategy max="20"/>
        </RollingRandomAccessFile>
    </appenders>
    <loggers>
        <!-- if you want to dump different packages to different files, here's where you do it
            <logger name="com.onuspride" level="DEBUG" additivity="false">
            <appender-ref ref="logFileOutput"/>
        </logger>-->
        <root level="debug" includeLocation="true">
            <!--<appender-ref ref="CONSOLE"/>-->
            <appender-ref ref="logFileOutput"/>
        </root>
    </loggers>
</configuration>

Answer 2

All looks good, I think you just need to set the log level of the root logger (looks like you already found that).

One small thing: in the RollingFile appender PatternLayout you are using %C. I recommend you use %c (lowercase) instead. %C walks the stack trace to get location info and will give much worse performance. (The log4j2 manual has more details.)