[
https://issues.apache.org/jira/browse/KARAF-6512?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16968471#comment-16968471
]
Frédéric Chuong commented on KARAF-6512:
----------------------------------------
That is a fair advice, but doesn't it also mean that a dead lock race condition
could still happen with lower log levels?
To give some more context, the reason for playing with log levels was trying to
identify the cause of random disconnections.
> Dead lock in LogServiceImpl
> ---------------------------
>
> Key: KARAF-6512
> URL: https://issues.apache.org/jira/browse/KARAF-6512
> Project: Karaf
> Issue Type: Bug
> Components: karaf
> Affects Versions: 4.2.7
> Environment: Windows 10
> {noformat}
> 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)
> {noformat}
> (this was also encountered with Java 8)
> Reporter: Frédéric Chuong
> Assignee: Jean-Baptiste Onofré
> Priority: Critical
> Attachments: FelixStartLevel.txt,
> sshd-SshServer[7df772af]-nio2-thread-2.txt,
> sshd-SshServer[7df772af]-nio2-thread-3.txt
>
>
> # Extract Karaf distribution
> # Start Karaf instance {{karaf}}
> # Open 2 clients (ssh)
> ## {{log:tail}}
> # In main initial console
> ## {{log:set DEBUG org.apache.sshd}}
> ## Perform some actions such as {{feature:repo-add cellar}},
> {{feature:install cellar}}
> # Sometime clients get disconnected, sometimes they are dead locked (use
> {{threads}} commands to see or use external process like {{jconsole}})
> # 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.
> {noformat}
> "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 [email protected]/java.security.AccessController.doPrivileged(Native
> Method)
> at
> org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37)
> at [email protected]/sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:127)
> at [email protected]/sun.nio.ch.Invoker$2.run(Invoker.java:219)
> at
> [email protected]/sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
> at
> [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
> at
> [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
> at [email protected]/java.lang.Thread.run(Thread.java:834)
> {noformat}
> {noformat}
> "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 [email protected]/java.io.PrintStream.write(PrintStream.java:559)
> - locked java.io.PrintStream@1bd7d088
> at
> [email protected]/sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:233)
> at
> [email protected]/sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:312)
> at
> [email protected]/sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
> - locked java.io.OutputStreamWriter@c263509
> at
> [email protected]/java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:184)
> at [email protected]/java.io.PrintStream.write(PrintStream.java:606)
> - locked java.io.PrintStream@1bd7d088
> at [email protected]/java.io.PrintStream.print(PrintStream.java:745)
> at [email protected]/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 [email protected]/java.security.AccessController.doPrivileged(Native
> Method)
> at
> org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:37)
> at [email protected]/sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:127)
> at [email protected]/sun.nio.ch.Invoker$2.run(Invoker.java:219)
> at
> [email protected]/sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)
> at
> [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
> at
> [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
> at [email protected]/java.lang.Thread.run(Thread.java:834)
> {noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
