Java Logging: Ninth Circle of Hell, a Gentle Introduction to Java Logging

Introduction to Java Logging Frameworks, given as an internal tech talk at FullContact

Transcript

1. Java Logging: Ninth Circle of Hell A Gentle Introduction to Java Logging April 18th, 2013 Thursday, April 18, 13
2. So you want to log something System.out.println(<x>); That’s it! Thursday, April 18, 13
3. Error logging If you’re Kyle (or sometimes me): println(“_______IN HERE ${important.var}”) println(“_________FFFFFUUUUU (${i})”) Thursday, April 18, 13
4. This is noise For the love of all that’s holy, use real logging We need more random output like we need AIDS Thursday, April 18, 13
5. Okay, so System.*.println() is so 1996, what’s the right way? Thursday, April 18, 13
6. The Right Way(TM) Thursday, April 18, 13
7. The Right Way(TM) So you’ve got... Thursday, April 18, 13
8. The Right Way(TM) So you’ve got... Jakarta Commons Logging (JCL, ACL) Thursday, April 18, 13
9. The Right Way(TM) So you’ve got... Jakarta Commons Logging (JCL, ACL) java.util.logging (JUL) Thursday, April 18, 13
10. The Right Way(TM) So you’ve got... Jakarta Commons Logging (JCL, ACL) java.util.logging (JUL) Apache Log4j Thursday, April 18, 13
11. The Right Way(TM) So you’ve got... Jakarta Commons Logging (JCL, ACL) java.util.logging (JUL) Apache Log4j SLF4J Thursday, April 18, 13
12. The Right Way(TM) So you’ve got... Jakarta Commons Logging (JCL, ACL) java.util.logging (JUL) Apache Log4j SLF4J Logback Thursday, April 18, 13
13. The Right Way(TM) So you’ve got... Jakarta Commons Logging (JCL, ACL) java.util.logging (JUL) Apache Log4j SLF4J Logback Blitz4j Thursday, April 18, 13
14. The Right Way(TM) So you’ve got... Jakarta Commons Logging (JCL, ACL) java.util.logging (JUL) Apache Log4j SLF4J Logback Blitz4j Apache Log4j2 Thursday, April 18, 13
15. The Right Way(TM) So you’ve got... Jakarta Commons Logging (JCL, ACL) java.util.logging (JUL) Apache Log4j SLF4J Logback Blitz4j Apache Log4j2 Proprietary crap Thursday, April 18, 13
16. The Right Way(TM) So you’ve got... Jakarta Commons Logging (JCL, ACL) java.util.logging (JUL) Apache Log4j SLF4J Logback Blitz4j Apache Log4j2 What. Proprietary crap Thursday, April 18, 13
17. How did we get here? What framework should we choose? Thursday, April 18, 13
18. A/S/L log4j (1999-2008) java.util.logging (2002) Jakarta Commons Logging (2002) Logback (2006-) SLF4J (2007-) Log4j2 (2012-) Blitz4j (??-) Thursday, April 18, 13
19. Thursday, April 18, 13
20. Thursday, April 18, 13
21. Logging Frameworks Thursday, April 18, 13
22. log4j Solid first choice, always a contender. Nobody was fired for using Log4j Old. You know you’re old when open Bugzilla tickets make it to primary school Pretty much dead. Little active development Java 4 compatible -- no Java 5 or 6 classes used, like Reentrant locks or CopyOnWrite lists for appenders Easily baffled if you step outside the box RollingFileAppender can deadlock easily Or reconfiguring Appenders at runtime, @Ken :) Thursday, April 18, 13
23. java.util.logging (JUL) log4j popped up when there was no logging Java introduced java.util.logging as a “standard” given log4j’s popularity It sucked in 1.4 and it sucks now Still better than println’s Advantage: Every VM since 1.4 has it Thursday, April 18, 13
24. Apache Commons Logging (JCL, ACL) Sort of like SLF4J, ‘ultra-thin facade’ JCP’s attempt to water down log4j Has serious issues with classloading If you’re using it, I weep for your children Thursday, April 18, 13
25. logback Successor of the log4j framework, many of the same developers Fixes many architectural issues More scalable (10x performance over log4j) Java code not written by prehistoric man “simply put, logback is just a better log4j” 3 packages: logback-core, logback-classic, logback-access logback-classic implements SLF4J natively Thursday, April 18, 13
26. logback-continued 14:28:48.835  [btpool0-­‐7]  INFO    c.q.l.demo.prime.PrimeAction  -­‐  99  is  not  a  valid  value java.lang.Exception:  99  is  invalid    at  ch.qos.logback.demo.prime.PrimeAction.execute(PrimeAction.java:28)  [classes/:na]    at  org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:431)  [struts-­‐1.2.9.jar:1.2.9]    at  org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:236)  [struts-­‐1.2.9.jar:1.2.9]    at  org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:432)  [struts-­‐1.2.9.jar:1.2.9]    at  javax.servlet.http.HttpServlet.service(HttpServlet.java:820)  [servlet-­‐api-­‐2.5-­‐6.1.12.jar:6.1.12]    at  org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)  [jetty-­‐6.1.12.jar:6.1.12]    at  ch.qos.logback.demo.UserServletFilter.doFilter(UserServletFilter.java:44)  [classes/:na]    at  org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1115)  [jetty-­‐6.1.12.jar:6.1.12]    at  org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:361)  [jetty-­‐6.1.12.jar:6.1.12]    at  org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:417)  [jetty-­‐6.1.12.jar:6.1.12]    at  org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230)  [jetty-­‐6.1.12.jar:6.1.12] HELL YEAH Packaging information! (If enabled) Thursday, April 18, 13
27. Blitz4j Written by Netflix, framework on top of log4j that doesn’t suck Uses modern Java More granular locks Summarization logback wasn’t an option when they started “Blitz4j is a logging framework built on top of log4j to reduce multithreaded contention and enable highly scalable logging without affecting application performance characteristics. ... Blitz4j makes runtime reconfigurations of log4j pretty easy. Blitz4j also tries to mitigate data loss and provides a way to summarize the log information during log storms.” Thursday, April 18, 13
28. Log4j2 Forked log4j - competes with logback Uses Java 5 and Java 6 improvements Log4j 1 and 2 are NOT 100% compatible. Also very good, on par with logback in performance Configurable with XML or JSON Up to 10x faster than log4j 1.2.x Thursday, April 18, 13
29. So WTF is SLF4J? Simple Logging Facade for Java Thursday, April 18, 13
30. SLF4J Not really a ‘logging framework’ A facade around logging which allows any underlying framework to handle logging Allows framework-to-framework bridges Libraries become logging framework-agnostic Developed by log4j’s founder, Ceki Gülcü Thursday, April 18, 13
31. Basic API, use everywhere private  static  Logger  log  =  LoggerFactory.getLogger(MyClass.class); log.info(“It  usually  just  {}”,  “works”); log.error(“Oh  no!”,  e); Avoid  this: static  final  Logger  log  =  org.apache.log4j.LogManager.getLogger(this) Dependency on log4j SLF4J style Parameterized logging! org.slf4j.* Thursday, April 18, 13
32. Performance Gotchas if (log.isDebugEnabled()) { log.debug(“xxx” + user.getId()); } Thursday, April 18, 13
33. Performance Gotchas if (log.isDebugEnabled()) { log.debug(“xxx” + user.getId()); } log.debug(“xxx {}”, user.getId()); 2x slower than If user.getId() is cheap. Otherwise use the if guard for expensive operations. Both avoid .toString() costs Thursday, April 18, 13
34. Log levels Pretty standard across implementations TRACE DEBUG INFO WARN ERROR FATAL Pretty self explanatory Thursday, April 18, 13
35. Diagnostic Contexts Contextual logging (e.g. thread name, userId) Available on log4j, logback, and log4j2 Two different types: Nested & Mapped Thursday, April 18, 13
36. NDC Nested Diagnostic Contexts are stacks NDC.push(“x”); NDC.pop(); Useful for debugging looping or recursive structures Thursday, April 18, 13
37. MDC Mapped Diagnostic Context key-value pairs MDC.put(“userId”, user.getId()) Usually what you’ll use Show up in Graylog using the Graylog Appender Thursday, April 18, 13
38. Use any logging framework Or no framework - /dev/null Thursday, April 18, 13
39. Don’t use log4j-over-slf4j and slf4j-over-log4j .:. Your application will not boot. Thursday, April 18, 13
40. SLF4J & Log4j log4j-over-slf4j - convert log4j-only projects to SLF4J e.x. library uses log4j, you’re on logback slf4j-log4j - Anything using the SLF4J API now uses log4j as a backend logger Thursday, April 18, 13
41. Framework Support Supports log4j, log4j2, logback, JCL, and JUL All you really need is slf4j-api (1.7.5+ preferred) Usually just have to include the proper framework-slf4j jar Can also spawn nasty dependency issues Data must flow in one direction, so choose yours and use dependency reports & exclusions to make it happen Thursday, April 18, 13
42. Keep an eye on dependencies Thursday, April 18, 13
43. SLF4J over JUL over JCL over log4j Thursday, April 18, 13
44. Don’t do that Thursday, April 18, 13
45. | Error SLF4J: Class path contains multiple SLF4J bindings. | Error SLF4J: Found binding in [jar:file:/Users/xorlev/.grails/ivy-cache/org.grails/grails-plugin-log4j/jars/grails-plugin-log4j-2.1.1.jar!/org/slf4j/impl/ StaticLoggerBinder.class] | Error SLF4J: Found binding in [jar:file:/Users/xorlev/.grails/ivy-cache/org.slf4j/slf4j-log4j12/jars/slf4j-log4j12-1.6.1.jar!/org/slf4j/impl/StaticLoggerBinder.class] | Error SLF4J: Found binding in [jar:file:/Users/xorlev/.grails/ivy-cache/org.slf4j/slf4j-nop/jars/slf4j-nop-1.6.4.jar!/org/slf4j/impl/StaticLoggerBinder.class] StackOverflowException log4j-over-slf4j & slf4j-log4j You aren’t a Java engineer until you’ve debugged SLF4J Thursday, April 18, 13
46. Implement SLF4J API in Libraries People I will thank you - It’s easy and just works* * Usually Thursday, April 18, 13
47. Configuring log4j & logback Thursday, April 18, 13
48. Appenders Send data places ConsoleAppender NTEventLogAppender SyslogAppender SMTPAppender GraylogAppender Implementing your own is easy Thursday, April 18, 13
49. Log4j Configured using log4j.properties files Issues? -Dlog4j.debug Thursday, April 18, 13
50. # Appender config log4j.appender.A1.File = ${storm.home}/logs/${logfile.name} log4j.appender.A1.Append = true log4j.appender.A1.DatePattern = '.'yyy-MM-dd log4j.appender.A1.layout = org.apache.log4j.PatternLayout log4j.appender.A1.layout.ConversionPattern = %d{yyyy-MM-dd HH:mm:ss} %c [%p] %m%n log4j.appender.graylog=org.graylog2.log.GelfAppender log4j.appender.graylog.graylogHost=graylog.site.com log4j.appender.graylog.facility=storm log4j.appender.graylog.extractStacktrace=true log4j.appender.graylog.addExtendedInformation=true log4j.appender.graylog.additionalFields={'environment': 'production', 'application': 'storm'} log4j.appender.graylog.Threshold=ERROR log4j.rootLogger=INFO, graylog, AI Thursday, April 18, 13
51. Logback Configured using logback.xml (or .groovy) Or programmatically https://github.com/smarchive/dropwizard-gelf/blob/ master/src/main/java/com/smarchive/dropwizard/ gelf/bundles/GelfLoggingBundle.java Thursday, April 18, 13
52. <configuration> <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{HH:mm:ss.SSS} TKD [%thread] %-5level %logger{36} - %msg%n </pattern> </encoder> </appender> <appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender"> <appender-ref ref="STDOUT" /> </appender> <root level="info"> <appender-ref ref="ASYNC" /> </root> </configuration> See https://github.com/Moocar/logback-gelf for a Graylog example Compose appenders Also works in log4j Thursday, April 18, 13
53. Questions? TL;DR: Use logback or log4j if you can Using the SLF4J API makes it easy to log without knowing what your host VM looks like e.x. Tomcat / Storm Log4j2 is still in alpha/beta Thursday, April 18, 13