[KARAF-6512] Dead lock in LogServiceImpl

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Won't Fix
• Affects Version/s: 4.2.7
• Component/s: karaf

Environment

Windows 10

Picked up JAVA_TOOL_OPTIONS: "-XX:+UsePerfData" "-Duser.language=en" "-Duser.country=US" "-Duser.timezone=UTC" "-Dfile.encoding=UTF-8"
openjdk version "11.0.4" 2019-07-16 LTS
OpenJDK Runtime Environment Zulu11.33+15-CA (build 11.0.4+11-LTS)
OpenJDK 64-Bit Server VM Zulu11.33+15-CA (build 11.0.4+11-LTS, mixed mode)

(this was also encountered with Java 8)

• Assignee: Jean-Baptiste Onofré
• Reporter: Frédéric Chuong
• Created: 06/Nov/19 15:35
• Updated: 06/Nov/19 16:04
• Resolved: 06/Nov/19 15:56

Description

1. Extract Karaf distribution
2. Start Karaf instance karaf
3. Open 2 clients (ssh)
   1. log:tail
4. In main initial console
   1. log:set DEBUG org.apache.sshd
   2. Perform some actions such as feature:repo-add cellar, feature:install cellar
5. Sometime clients get disconnected, sometimes they are dead locked (use threads commands to see or use external process like jconsole)
6. When dead lock happen, SSH server does not respond to new connections

This can also happen when log:tail is executing from the main console, rendering the console ineffective.

"sshd-SshServer[46bcb190]-nio2-thread-3" Id=146 in BLOCKED on lock=org.apache.karaf.log.core.internal.LogServiceImpl@46fdf7b8
     owned by sshd-SshServer[46bcb190]-nio2-thread-4 Id=147
    at org.apache.karaf.log.core.internal.LogServiceImpl.doAppend(LogServiceImpl.java:176)
    at org.ops4j.pax.logging.spi.support.PaxAppenderProxy.doAppend(PaxAppenderProxy.java:69)
    at org.ops4j.pax.logging.log4j2.internal.bridges.PaxOsgiAppender.append(PaxOsgiAppender.java:100)
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:543)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:502)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485)
    at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:534)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:504)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:412)
    at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:154)
    at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog0(PaxLoggerImpl.java:354)
    at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog(PaxLoggerImpl.java:337)
    at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.debug(PaxLoggerImpl.java:142)
    at org.ops4j.pax.logging.internal.TrackingLogger.debug(TrackingLogger.java:115)
    at org.ops4j.pax.logging.slf4j.Slf4jLogger.debug(Slf4jLogger.java:340)
    at org.apache.sshd.common.io.nio2.Nio2Session.writePacket(Nio2Session.java:136)
    at org.apache.sshd.common.session.helpers.AbstractSession.doWritePacket(AbstractSession.java:1154)
      - locked java.lang.Object@76a33827
    at org.apache.sshd.common.session.helpers.AbstractSession.writePacket(AbstractSession.java:1096)
    at org.apache.sshd.common.channel.AbstractChannel.sendResponse(AbstractChannel.java:369)
    at org.apache.sshd.server.channel.ChannelSession.sendResponse(ChannelSession.java:336)
    at org.apache.sshd.common.channel.AbstractChannel.handleChannelRequest(AbstractChannel.java:302)
    at org.apache.sshd.common.channel.AbstractChannel.handleRequest(AbstractChannel.java:270)
    at org.apache.sshd.common.session.helpers.AbstractConnectionService.channelRequest(AbstractConnectionService.java:517)
    at org.apache.sshd.common.session.helpers.AbstractConnectionService.process(AbstractConnectionService.java:341)
    at org.apache.sshd.common.session.helpers.AbstractSession.doHandleMessage(AbstractSession.java:614)
    at org.apache.sshd.common.session.helpers.AbstractSession.handleMessage(AbstractSession.java:547)
      - locked java.lang.Object@1da148eb
    at org.apache.sshd.common.session.helpers.AbstractSession.decode(AbstractSession.java:1498)
    at org.apache.sshd.common.session.helpers.AbstractSession.messageReceived(AbstractSession.java:508)
      - locked java.lang.Object@430f279b
    at org.apache.sshd.common.session.helpers.AbstractSessionIoHandler.messageReceived(AbstractSessionIoHandler.java:66)
    at org.apache.sshd.common.io.nio2.Nio2Session.handleReadCycleCompletion(Nio2Session.java:301)
    at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:281)
    at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:278)
    at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38)
    at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$$Lambda$562/0x0000000100634840.run(Unknown Source)
    at java.base@11.0.4/java.security.AccessController.doPrivileged(Native Method)
    at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37)
    at java.base@11.0.4/sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:127)
    at java.base@11.0.4/sun.nio.ch.Invoker$2.run(Invoker.java:219)
    at java.base@11.0.4/sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
    at java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.4/java.lang.Thread.run(Thread.java:834)

"sshd-SshServer[46bcb190]-nio2-thread-4" Id=147 in BLOCKED on lock=java.lang.Object@76a33827
     owned by sshd-SshServer[46bcb190]-nio2-thread-3 Id=146
    at org.apache.sshd.common.session.helpers.AbstractSession.doWritePacket(AbstractSession.java:1147)
    at org.apache.sshd.common.session.helpers.AbstractSession.writePacket(AbstractSession.java:1096)
    at org.apache.sshd.common.channel.AbstractChannel.writePacket(AbstractChannel.java:794)
    at org.apache.sshd.common.channel.ChannelOutputStream.flush(ChannelOutputStream.java:221)
      - locked org.apache.sshd.common.channel.ChannelOutputStream@397cee8f
    at org.jline.terminal.impl.LineDisciplineTerminal$FilteringOutputStream.flush(LineDisciplineTerminal.java:301)
    at org.jline.terminal.impl.LineDisciplineTerminal$FilteringOutputStream.write(LineDisciplineTerminal.java:296)
    at java.base@11.0.4/java.io.PrintStream.write(PrintStream.java:559)
      - locked java.io.PrintStream@1bd7d088
    at java.base@11.0.4/sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:233)
    at java.base@11.0.4/sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:312)
    at java.base@11.0.4/sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
      - locked java.io.OutputStreamWriter@c263509
    at java.base@11.0.4/java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:184)
    at java.base@11.0.4/java.io.PrintStream.write(PrintStream.java:606)
      - locked java.io.PrintStream@1bd7d088
    at java.base@11.0.4/java.io.PrintStream.print(PrintStream.java:745)
    at java.base@11.0.4/java.io.PrintStream.append(PrintStream.java:1147)
    at org.apache.karaf.log.command.DisplayLog.printEvent(DisplayLog.java:126)
    at org.apache.karaf.log.command.DisplayLog.printEvent(DisplayLog.java:110)
    at org.apache.karaf.log.command.LogTail.lambda$execute$0(LogTail.java:52)
    at org.apache.karaf.log.command.LogTail$$Lambda$611/0x00000001006b9c40.doAppend(Unknown Source)
    at org.apache.karaf.log.core.internal.LogServiceImpl.doAppend(LogServiceImpl.java:181)
      - locked org.apache.karaf.log.core.internal.LogServiceImpl@46fdf7b8
    at org.ops4j.pax.logging.spi.support.PaxAppenderProxy.doAppend(PaxAppenderProxy.java:69)
    at org.ops4j.pax.logging.log4j2.internal.bridges.PaxOsgiAppender.append(PaxOsgiAppender.java:100)
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:543)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:502)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485)
    at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:534)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:504)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:485)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:412)
    at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
    at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:154)
    at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog0(PaxLoggerImpl.java:354)
    at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog(PaxLoggerImpl.java:337)
    at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.debug(PaxLoggerImpl.java:142)
    at org.ops4j.pax.logging.internal.TrackingLogger.debug(TrackingLogger.java:115)
    at org.ops4j.pax.logging.slf4j.Slf4jLogger.debug(Slf4jLogger.java:340)
    at org.apache.sshd.common.io.nio2.Nio2Session.handleCompletedWriteCycle(Nio2Session.java:397)
    at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:372)
    at org.apache.sshd.common.io.nio2.Nio2Session$2.onCompleted(Nio2Session.java:369)
    at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.lambda$completed$0(Nio2CompletionHandler.java:38)
    at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$$Lambda$562/0x0000000100634840.run(Unknown Source)
    at java.base@11.0.4/java.security.AccessController.doPrivileged(Native Method)
    at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37)
    at java.base@11.0.4/sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:127)
    at java.base@11.0.4/sun.nio.ch.Invoker$2.run(Invoker.java:219)
    at java.base@11.0.4/sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
    at java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base@11.0.4/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base@11.0.4/java.lang.Thread.run(Thread.java:834)