jurmous / logstash-log4j2

Log4j2 plugin for logstash
41 stars 21 forks source link

Missing lmax disruptor jar for log4j2 asynchronous loggers #7

Closed SaucyWrong closed 9 years ago

SaucyWrong commented 9 years ago

Using release 4.0 of this excellent plugin, it appears that the disruptor jar used by log4j when using globally-asyn loggers as documented here: http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync

the plugin complains that it can't find a class when I attempt to ship it a log using an asynchronous socket appender:

Pipeline started {:level=>:info, :file=>"logstash/pipeline.rb", :line=>"78"}
Accepted connection {:client=>"127.0.0.1:54923", :server=>"0.0.0.0:4560", :level=>:debug, :file=>"./logstash-1.4.2/third_party_plugins/log4j2/lib/logstash/inputs/log4j2.rb", :line=>"150"}
com/lmax/disruptor/EventFactory {:level=>:debug, :exception=>Java::JavaLang::NoClassDefFoundError, :backtrace=>["java.lang.ClassLoader.defineClass1(Native Method)", "java.lang.ClassLoader.defineClass(ClassLoader.java:800)", "java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)", "java.net.URLClassLoader.defineClass(URLClassLoader.java:449)", "java.net.URLClassLoader.access$100(URLClassLoader.java:71)", "java.net.URLClassLoader$1.run(URLClassLoader.java:361)", "java.net.URLClassLoader$1.run(URLClassLoader.java:355)", "java.security.AccessController.doPrivileged(Native Method)", "java.net.URLClassLoader.findClass(URLClassLoader.java:354)", "org.jruby.util.JRubyClassLoader.findClass(JRubyClassLoader.java:128)", "java.lang.ClassLoader.loadClass(ClassLoader.java:425)", "java.lang.ClassLoader.loadClass(ClassLoader.java:358)", "org.apache.logging.log4j.core.async.RingBufferLogEvent.<clinit>(RingBufferLogEvent.java:56)", "java.lang.Class.forName0(Native Method)", "java.lang.Class.forName(Class.java:274)", "org.jruby.ext.jruby.JRubyObjectInputStream$JRubyObjectInputStreamImpl.resolveClass(JRubyObjectInputStream.java:84)", "java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1612)", "java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1517)", "java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1771)", "java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1350)", "java.io.ObjectInputStream.readObject(ObjectInputStream.java:370)", "org.jruby.ext.jruby.JRubyObjectInputStream.readObject(JRubyObjectInputStream.java:56)", "org.jruby.ext.jruby.JRubyObjectInputStream$INVOKER$i$0$0$readObject.call(JRubyObjectInputStream$INVOKER$i$0$0$readObject.gen)", "org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:56)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:306)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:136)", "org.jruby.ast.CallNoArgNode.interpret(CallNoArgNode.java:60)", "org.jruby.ast.DAsgnNode.interpret(DAsgnNode.java:110)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.ast.BlockNode.interpret(BlockNode.java:71)", "org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)", "org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)", "org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:157)", "org.jruby.runtime.Interpreted19Block.yieldSpecific(Interpreted19Block.java:130)", "org.jruby.runtime.Block.yieldSpecific(Block.java:111)", "org.jruby.RubyKernel.loop(RubyKernel.java:1521)", "org.jruby.RubyKernel$INVOKER$s$0$0$loop.call(RubyKernel$INVOKER$s$0$0$loop.gen)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:316)", "org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:145)", "org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:154)", "org.jruby.ast.FCallNoArgBlockNode.interpret(FCallNoArgBlockNode.java:32)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.ast.BlockNode.interpret(BlockNode.java:71)", "org.jruby.ast.RescueNode.executeBody(RescueNode.java:221)", "org.jruby.ast.RescueNode.interpret(RescueNode.java:116)", "org.jruby.ast.BeginNode.interpret(BeginNode.java:83)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.ast.EnsureNode.interpret(EnsureNode.java:96)", "org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)", "org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:225)", "org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:214)", "org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:346)", "org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:204)", "org.jruby.ast.FCallTwoArgNode.interpret(FCallTwoArgNode.java:38)", "org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)", "org.jruby.ast.BlockNode.interpret(BlockNode.java:71)", "org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)", "org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)", "org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:194)", "org.jruby.runtime.Interpreted19Block.call(Interpreted19Block.java:125)", "org.jruby.runtime.Block.call(Block.java:101)", "org.jruby.RubyProc.call(RubyProc.java:290)", "org.jruby.RubyProc.call(RubyProc.java:228)", "org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:99)", "java.lang.Thread.run(Thread.java:745)"], :file=>"./logstash-1.4.2/third_party_plugins/log4j2/lib/logstash/inputs/log4j2.rb", :line=>"114"}
Closing connection {:client=>"127.0.0.1:54923", :exception=>java.lang.NoClassDefFoundError: com/lmax/disruptor/EventFactory, :level=>:debug, :file=>"./logstash-1.4.2/third_party_plugins/log4j2/lib/logstash/inputs/log4j2.rb", :line=>"115"}

The disruptor jar seems to be required when you work with the asynchronous loggers using the -DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector.

The concept of asynchronous loggers is new in Log4j2 and is different from wrapping a socket appender with an asynchronous appender.

I tried manually placing the jar in the vendor subfolder of the plugin, but that did not do anything. Is this method of shipping logs to your plugin supported?

jurmous commented 9 years ago

This method is probably not yet supported since I have never tested it out. The wrapping of a socket appender in an asynchronous appender is supported though.

Can you share your log4j2.xml?

SaucyWrong commented 9 years ago

Sure thing--I'm using the yml config format and it looks something like this (I deleted certain things that weren't relevant, such as the root logger, which is just a normal RollingRandomAccessFile appender:

%YAML 1.1
---
Configuration:
  appenders:
    appender:
      - type: Socket
        name: SOCKET
        host: localhost
        port: 4560
        immediateFail: true
        immediateFlush: true
  loggers:
    root:
      level: warn
      AppenderRef:
        - ref: ROOT_LOG
    logger:
      - name: com.foo.bar.MyClass
        level: ALL
        additivity: false
        AppenderRef:
          - ref: SOCKET

You'll notice that these appenders and loggers look normal--there is nothing in the config file to indicate that they are asynchronous.

Instead, I supply the following JVM property at runtime:

-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector

This tells log4j2 that it should use the Disruptor to asynchronously handle all logging activity. It would seem that this requires the disruptor jar to be present on the classpath for both the program doing the logging and the program that is acting as the log4j2 server (your plugin, in this case).

SaucyWrong commented 9 years ago

Incidentally, it appears that adding the necessary jar and then requiring it in the Ruby code does allow the plugin to successfully handle asynchronous loggers. I'm sure you'll want to test this yourself, but this appears to work for me.

Here is the code change I made to the plugin in my environment:

    begin
      vendor_dir = ::File.expand_path("../../../vendor/", ::File.dirname(__FILE__))
      require File.join(vendor_dir, "log4j-api-2.1.jar")
      require File.join(vendor_dir, "log4j-core-2.1.jar")
      require File.join(vendor_dir, "disruptor-3.3.0.jar")

And I obtained the disruptor jar from http://search.maven.org/#artifactdetails%7Ccom.lmax%7Cdisruptor%7C3.3.0%7Cjar

I don't believe any other changes to the plugin are required--I think this jar is just needed by log4j2 so if a message comes in the disruptor format it can unwrap it properly.

jurmous commented 9 years ago

I have released 5.0 with the fix you mentioned. Does it work for you? If confirmed I will close this issue. Thanks for all the help!

SaucyWrong commented 9 years ago

This fix works for me. Thanks for the great plugin!

jurmous commented 9 years ago

You are welcome! Thanks for reporting this issue! If you encounter any problems or have any suggestions please report them :smile: