Skip to content
This repository has been archived by the owner on Jun 29, 2023. It is now read-only.

Gelf logger configured on JBoss cause deadlock during server stopping #57

Closed
ViktarPatsiaichuk opened this issue Dec 7, 2015 · 8 comments
Closed

Gelf logger configured on JBoss cause deadlock during server stopping #57

ViktarPatsiaichuk opened this issue Dec 7, 2015 · 8 comments
Labels
type: bug A general bug
Milestone
logstash-gelf 1.8.0

Comments

@ViktarPatsiaichuk
Copy link

Gelf_logger_deadlock_details.docx
@mp911de
Copy link
Owner

mp911de commented Dec 7, 2015

Issue description

JBoss server hangs during stopping.

The reason of issue: GelfLogHandler internal logging (line 127). Check JBoss configuration and threads dump for more details.

JBoss configuration

     <profile name="<REPLACED> ">
            <subsystem xmlns="urn:jboss:domain:logging:1.3">
                <console-handler name="CONSOLE">
                    <formatter>
                        <pattern-formatter pattern="%K{level}%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
                    </formatter>
                </console-handler>
                <custom-handler name="GELF-LOGGER" class="biz.paluch.logging.gelf.jboss7.JBoss7GelfLogHandler" module="biz.paluch.logging">
                    <level name="INFO"/>
                    <properties>
                        <property name="host" value="udp:localhost"/>
                        <property name="port" value="12201"/>
                        <property name="extractStackTrace" value="true"/>
                        <property name="filterStackTrace" value="true"/>
                        <property name="mdcProfiling" value="true"/>
                        <property name="timestampPattern" value="yyyy-MM-dd HH:mm:ss,SSSS"/>
                        <property name="maximumMessageSize" value="8192"/>
                        <property name="additionalFields" value="_landscape=<REPLACED>"/>
                        <property name="mdcFields" value="_system,_component_name,_component.version,_sma_id,_client_ip,_session_id,_correlation_id"/>
                        <property name="dynamicMdcFields" value="mdc.*,(mdc|MDC)fields"/>
                        <property name="includeFullMdc" value="true"/>
                    </properties>
                </custom-handler>
                <periodic-rotating-file-handler name="FILE" autoflush="true">
                    <formatter>
                        <pattern-formatter pattern="%d{HH:mm:ss,SSS} %-5p [%c] (%t) %s%E%n"/>
                    </formatter>
                    <file relative-to="jboss.server.log.dir" path="server.log"/>
                    <suffix value=".yyyy-MM-dd"/>
                    <append value="true"/>
                </periodic-rotating-file-handler>
                <logger category="<REPLACED>" use-parent-handlers="false">
                    <level name="DEBUG"/>
                    <handlers>
                        <handler name="CONSOLE"/>
                        <handler name="FILE"/>
                        <handler name="GELF-LOGGER"/>
                    </handlers>
                </logger>
                <root-logger>
                    <level name="INFO"/>
                    <handlers>
                        <handler name="CONSOLE"/>
                        <handler name="FILE"/>
                        <handler name="GELF-LOGGER"/>
                    </handlers>
                </root-logger>
            </subsystem>

Threads dump

Found one Java-level deadlock:

=============================
"Thread-32 (HornetQ-client-global-threads-79116542)":
  waiting to lock monitor 0x00000000019ae968 (object 0x0000000724d0b318, a java.util.logging.ErrorManager),
  which is held by "ServerSocketListener"
"ServerSocketListener":
  waiting to lock monitor 0x00007f6b280e9238 (object 0x0000000724d2a4a0, a java.io.PrintStream),
  which is held by "pool-6-thread-2"
"pool-6-thread-2":
  waiting to lock monitor 0x00000000019ae968 (object 0x0000000724d0b318, a java.util.logging.ErrorManager),
  which is held by "ServerSocketListener"

Java stack information for the threads listed above:

"Thread-32 (HornetQ-client-global-threads-79116542)":
    at java.util.logging.ErrorManager.error(ErrorManager.java:84)
    - waiting to lock <0x0000000724d0b318> (a java.util.logging.ErrorManager)
    at java.util.logging.Handler.reportError(Handler.java:232)
    at biz.paluch.logging.gelf.jul.GelfLogHandler.reportError(GelfLogHandler.java:127)
    at biz.paluch.logging.gelf.intern.sender.GelfUDPSender.sendDatagrams(GelfUDPSender.java:55)
    at biz.paluch.logging.gelf.intern.sender.GelfUDPSender.sendMessage(GelfUDPSender.java:46)
    at biz.paluch.logging.gelf.jul.GelfLogHandler.publish(GelfLogHandler.java:113)
    at biz.paluch.logging.gelf.jboss7.JBoss7GelfLogHandler.publish(JBoss7GelfLogHandler.java:84)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:296)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    at org.jboss.logmanager.Logger.logRaw(Logger.java:721)
    at org.jboss.logmanager.Logger.log(Logger.java:672)
    at org.jboss.logging.JBossLogManagerLogger.doLog(JBossLogManagerLogger.java:42)
    at org.jboss.logging.Logger.logv(Logger.java:1951)
    at org.hornetq.core.client.HornetQClientLogger_$logger.connectionFailureDetected(HornetQClientLogger_$logger.java:629)
    at org.hornetq.core.protocol.core.impl.RemotingConnectionImpl.fail(RemotingConnectionImpl.java:338)
    at org.hornetq.core.client.impl.ClientSessionFactoryImpl$CloseRunnable.run(ClientSessionFactoryImpl.java:1640)
    at org.hornetq.utils.OrderedExecutorFactory$OrderedExecutor$1.run(OrderedExecutorFactory.java:105)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)
"ServerSocketListener":
    at java.io.PrintStream.println(PrintStream.java:806)
    - waiting to lock <0x0000000724d2a4a0> (a java.io.PrintStream)
    at org.jboss.stdio.StdioContext$DelegatingPrintStream.println(StdioContext.java:474)
    at java.util.logging.ErrorManager.error(ErrorManager.java:94)
    - locked <0x0000000724d0b318> (a java.util.logging.ErrorManager)
    at java.util.logging.Handler.reportError(Handler.java:232)
    at biz.paluch.logging.gelf.jul.GelfLogHandler.reportError(GelfLogHandler.java:127)
    at biz.paluch.logging.gelf.intern.sender.GelfUDPSender.sendDatagrams(GelfUDPSender.java:55)
    at biz.paluch.logging.gelf.intern.sender.GelfUDPSender.sendMessage(GelfUDPSender.java:46)
    at biz.paluch.logging.gelf.jul.GelfLogHandler.publish(GelfLogHandler.java:113)
    at biz.paluch.logging.gelf.jboss7.JBoss7GelfLogHandler.publish(JBoss7GelfLogHandler.java:84)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:296)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    at org.jboss.logmanager.Logger.logRaw(Logger.java:721)
    at org.slf4j.impl.Slf4jLogger.log(Slf4jLogger.java:326)
    at org.slf4j.impl.Slf4jLogger.log(Slf4jLogger.java:320)
    at org.slf4j.impl.Slf4jLogger.info(Slf4jLogger.java:180)
    at org.jacorb.orb.iiop.IIOPListener$Acceptor.run(IIOPListener.java:456)
    - locked <0x000000071e355d58> (a java.lang.Object)
"pool-6-thread-2":
    at java.util.logging.ErrorManager.error(ErrorManager.java:84)
    - waiting to lock <0x0000000724d0b318> (a java.util.logging.ErrorManager)
    at java.util.logging.Handler.reportError(Handler.java:232)
    at biz.paluch.logging.gelf.jul.GelfLogHandler.reportError(GelfLogHandler.java:127)
    at biz.paluch.logging.gelf.intern.sender.GelfUDPSender.sendDatagrams(GelfUDPSender.java:55)
    at biz.paluch.logging.gelf.intern.sender.GelfUDPSender.sendMessage(GelfUDPSender.java:46)
    at biz.paluch.logging.gelf.jul.GelfLogHandler.publish(GelfLogHandler.java:113)
    at biz.paluch.logging.gelf.jboss7.JBoss7GelfLogHandler.publish(JBoss7GelfLogHandler.java:84)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:296)
    at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:304)
    at org.jboss.logmanager.Logger.logRaw(Logger.java:721)
    at org.jboss.logmanager.Logger.log(Logger.java:506)
    at org.jboss.stdio.AbstractLoggingWriter.write(AbstractLoggingWriter.java:71)
    - locked <0x0000000724d2a508> (a java.lang.StringBuilder)
    at org.jboss.stdio.WriterOutputStream.finish(WriterOutputStream.java:143)
    at org.jboss.stdio.WriterOutputStream.flush(WriterOutputStream.java:164)
    - locked <0x0000000724d2a648> (a sun.nio.cs.UTF_8$Decoder)
    at java.io.PrintStream.write(PrintStream.java:482)
    - locked <0x0000000724d2a4a0> (a java.io.PrintStream)
    at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
    at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
    at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
    - locked <0x0000000724d2aa20> (a java.io.OutputStreamWriter)
    at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
    at java.io.PrintStream.newLine(PrintStream.java:546)
    - locked <0x0000000724d2a4a0> (a java.io.PrintStream)
    at java.io.PrintStream.println(PrintStream.java:824)
    - locked <0x0000000724d2a4a0> (a java.io.PrintStream)
    at org.jboss.stdio.StdioContext$DelegatingPrintStream.println(StdioContext.java:486)
    at java.lang.Throwable$WrappedPrintStream.println(Throwable.java:748)
    at java.lang.Throwable.printStackTrace(Throwable.java:658)
    - locked <0x0000000724ca9470> (a org.jboss.stdio.StdioContext$2)
    at java.lang.Throwable.printStackTrace(Throwable.java:643)
    at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:1061)
    at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:1052)
    at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:1052)
    at java.lang.Thread.dispatchUncaughtException(Thread.java:1986)

Found 1 deadlock.

@mp911de
Copy link
Owner

mp911de commented Dec 7, 2015

There are two issues within this ticket:

  1. The GELF appender runs into I/O errors and tries to report those
  2. While reporting I/O errors, the error reporting facility is locked by the JBoss log manager framework . An unhandled exception occurred in thread pool-6-thread-2 that is reported to stderr.

Now take these two items into account: The stderr stream is locked while logstash-gelf tries to report an error and so the deadlock happens. The evil thing here is that the error stream of the ErrorHandler feeds back into the JBoss log manager, and, therefore, the deadlock occurs.

I fear that I can't help you much. Please report this error to the JBoss issue tracker (http://issues.jboss.org) or the JBoss community (http://community.jboss.org)

@mp911de mp911de added the type: bug A general bug label Dec 7, 2015
@ViktarPatsiaichuk
Copy link
Author

Thanks for response.
From my point of view it is bad idea to report Gelf internal errors, because here we write errors to source from where we get an errors (endless loop). Can you introduce additional property for controlling whenever Gelf should report it internal errors.

@mp911de
Copy link
Owner

mp911de commented Dec 8, 2015

The error logging is on purpose and conforms with the JUL API guide. Without error logging, there's no possibility to trace problems. I'll update this ticket as soon I can provide a suitable solution.

@mp911de
Copy link
Owner

mp911de commented Dec 12, 2015

This problem was fixed in the newer JBoss AS versions (see https://bugzilla.redhat.com/show_bug.cgi?id=969126 and jboss-logging/jboss-logmanager#18). I'm not convinced that a silent mode is a right approach. It's more a workaround patch for the particular constellation. If you can't update your application server, fork the repo and create a patched version.

@mp911de mp911de added the status: invalid An issue that we don't feel is valid label Dec 12, 2015
@ViktarPatsiaichuk
Copy link
Author

We use JBoss EAP 6.2 with jboss-logmanager-1.5.2.Final-redhat-1.jar. This version of log-manager includes fix: jboss-logging/jboss-logmanager#18

The problem is here what fix is applied in org\jboss\logmanager\ExtHandler and relevant only for handlers extended from this class (e.g for org\jboss\logmanager\handlers\AsyncHandler, org\jboss\logmanager\handlers\ConsoleHandler, etc), but not for JBoss7GelfLogHandler.

@mp911de mp911de removed the status: invalid An issue that we don't feel is valid label Dec 14, 2015
@mp911de
Copy link
Owner

mp911de commented Dec 14, 2015

True, my bad. I will adopt the same approach and the issue should be then fixed.

mp911de added a commit that referenced this issue Dec 17, 2015
@mp911de
Use OnlyOnceErrorManager to prevent deadlocks while reporting errors #57
5c64bdb
@mp911de mp911de added this to the logstash-gelf 1.8.0 milestone Jan 5, 2016
@mp911de
Copy link
Owner

mp911de commented Jan 5, 2016

Fix implemented.

@mp911de mp911de closed this as completed Jan 5, 2016
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
type: bug A general bug
Projects
None yet
Milestone
logstash-gelf 1.8.0
Development

No branches or pull requests
2 participants
@mp911de @ViktarPatsiaichuk