Uploaded image for project: 'Karaf'
  1. Karaf
  2. KARAF-6512

Dead lock in LogServiceImpl

    XMLWordPrintableJSON

    Details

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

      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)
      

        Attachments

        1. FelixStartLevel.txt
          4 kB
          Frédéric Chuong
        2. sshd-SshServer[7df772af]-nio2-thread-2.txt
          4 kB
          Frédéric Chuong
        3. sshd-SshServer[7df772af]-nio2-thread-3.txt
          5 kB
          Frédéric Chuong

          Activity

            People

            • Assignee:
              jbonofre Jean-Baptiste Onofré
              Reporter:
              chuong_f Frédéric Chuong
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: