Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

SimpleReferenceManager / Logging deadlock #2086

Closed
devinrsmith opened this issue Mar 10, 2022 · 3 comments · Fixed by #2511
Closed

SimpleReferenceManager / Logging deadlock #2086

devinrsmith opened this issue Mar 10, 2022 · 3 comments · Fixed by #2511
Assignees
@nbauernfeind
Labels
bug Something isn't working console grpc jetty
Milestone
Jun 2022

Comments

@devinrsmith
Copy link
Member

Deadlock running on jetty server.

"ProcessMemoryTracker.Driver":                                                                                                                                                                                                                                                                                                                                                                                                              
        at io.deephaven.io.logger.LogBuffer.record(LogBuffer.java:46)                                                                                                                                                                                                                                                                                                                                                                       
        - waiting to lock <0x0000000082151358> (a io.deephaven.io.logger.LogBufferInterceptor)                                                                                                                                                                                                                                                                                                                                              
        at io.deephaven.logback.LogBufferAppender.append(LogBufferAppender.java:57)                                                                                                                                                                                                                                                                                                                                                         
        at io.deephaven.logback.LogBufferAppender.append(LogBufferAppender.java:15)                                                                                                                                                                                                                                                                                                                                                         
        at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)                                                                                                                                                                                                                                                                                                                                      
        at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:50)                                                                                                                                                                                                                                                                                                                             
        at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)                                                                                                                                                                                                                                                                                                                                                             
        at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)                                                                                                                                                                                                                                                                                                                                                                     
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:423)                                                                                                                                                                                                                                                                                                                                                        
        at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:385)                                                                                                                                                                                                                                                                                                                                                            
        at ch.qos.logback.classic.Logger.info(Logger.java:597)                                                                                                                                                                                                                                                                                                                                                                              
        at io.deephaven.internal.log.LoggerSlf4j$Sink.write(LoggerSlf4j.java:156)                                                                                                                                                                                                                                                                                                                                                           
        at io.deephaven.internal.log.LoggerSlf4j$Sink.write(LoggerSlf4j.java:114)                                                                                                                                                                                                                                                                                                                                                           
        at io.deephaven.io.log.impl.LogEntryImpl.end(LogEntryImpl.java:78)                                                                                                                                                                                                                                                                                                                                                                  
        at io.deephaven.internal.log.LoggerSlf4j$Entry.endl(LoggerSlf4j.java:99)                                                                                                                                                                                                                                                                                                                                                            
        at io.deephaven.engine.table.impl.util.RuntimeMemory.read(RuntimeMemory.java:181)                                                                                                                                                                                                                                                                                                                                                   
        - locked <0x0000000086b18a38> (a io.deephaven.engine.table.impl.util.RuntimeMemory)                                                                                                                                                                                                                                                                                                                                                 
        at io.deephaven.engine.table.impl.util.ProcessMemoryTracker$Driver.run(ProcessMemoryTracker.java:69)                                                                                                                                                                                                                                                                                                                                
        at java.lang.Thread.run(java.base@11.0.14.1/Thread.java:829) 
        
"Thread-99":                                                                                                                                                                                                                                                                                                                                                                                                                                
        at io.deephaven.server.session.SessionState.removeOnCloseCallback(SessionState.java:406)                                                                                                                                                                                                                                                                                                                                            
        - waiting to lock <0x00000000864db808> (a io.deephaven.util.datastructures.SimpleReferenceManager)                                                                                                                                                                                                                                                                                                                                  
        at io.deephaven.server.session.SessionCloseableObserver.close(SessionCloseableObserver.java:26)                                                                                                                                                                                                                                                                                                                                     
        at io.deephaven.server.console.ConsoleServiceGrpcImpl$LogBufferStreamAdapter.record(ConsoleServiceGrpcImpl.java:475)                                                                                                                                                                                                                                                                                                                
        at io.deephaven.io.logger.LogBuffer.recordInternal(LogBuffer.java:39)                                                                                                                                                                                                                                                                                                                                                               
        - locked <0x0000000082151358> (a io.deephaven.io.logger.LogBufferInterceptor)                                                                                                                                                                                                                                                                                                                                                       
        at io.deephaven.io.logger.LogBufferOutputStream.record(LogBufferOutputStream.java:45)                                                                                                                                                                                                                                                                                                                                               
        at io.deephaven.io.logger.LogBufferOutputStream.write(LogBufferOutputStream.java:32)                                                                                                                                                                                                                                                                                                                                                
        - locked <0x0000000083145898> (a io.deephaven.io.logger.LogBufferOutputStream)                                                                                                                                                                                                                                                                                                                                                      
        at java.io.OutputStream.write(java.base@11.0.14.1/OutputStream.java:157)                                                                                                                                                                                                                                                                                                                                                            
        at io.deephaven.base.system.MultipleOutputStreams.write(MultipleOutputStreams.java:42)                                                                                                                                                                                                                                                                                                                                              
        - locked <0x0000000083145838> (a io.deephaven.base.system.MultipleOutputStreams)                                                                                                                                                                                                                                                                                                                                                    
        at java.io.PrintStream.write(java.base@11.0.14.1/PrintStream.java:559)                                                                                                                                                                                                                                                                                                                                                              
        - locked <0x0000000083145810> (a java.io.PrintStream)                                                                                                                                                                                                                                                                                                                                                                               
        at sun.nio.cs.StreamEncoder.writeBytes(java.base@11.0.14.1/StreamEncoder.java:233)                                                                                                                                                                                                                                                                                                                                                  
        at sun.nio.cs.StreamEncoder.implFlushBuffer(java.base@11.0.14.1/StreamEncoder.java:312)                                                                                                                                                                                                                                                                                                                                             
        at sun.nio.cs.StreamEncoder.flushBuffer(java.base@11.0.14.1/StreamEncoder.java:104)                                                                                                                                                                                                                                                                                                                                                 
        - locked <0x0000000083145a70> (a java.io.OutputStreamWriter)                                                                                                                                                                                                                                                                                                                                                                        
        at java.io.OutputStreamWriter.flushBuffer(java.base@11.0.14.1/OutputStreamWriter.java:181)                                                                                                                                                                                                                                                                                                                                          
        at java.io.PrintStream.newLine(java.base@11.0.14.1/PrintStream.java:625)                                                                                                                                                                                                                                                                                                                                                            
        - locked <0x0000000083145810> (a java.io.PrintStream)                                                                                                                                                                                                                                                                                                                                                                               
        at java.io.PrintStream.println(java.base@11.0.14.1/PrintStream.java:900)                                                                                                                                                                                                                                                                                                                                                            
        - locked <0x0000000083145810> (a java.io.PrintStream)                                                                                                                                                                                                                                                                                                                                                                               
        at java.lang.Throwable$WrappedPrintStream.println(java.base@11.0.14.1/Throwable.java:752)                                                                                                                                                                                                                                                                                                                                           
        at java.lang.Throwable.printStackTrace(java.base@11.0.14.1/Throwable.java:662)                                                                                                                                                                                                                                                                                                                                                      
        - locked <0x0000000083145810> (a java.io.PrintStream)                                                                                                                                                                                                                                                                                                                                                                               
        at java.lang.Throwable.printStackTrace(java.base@11.0.14.1/Throwable.java:648)                                                                                                                                                                                                                                                                                                                                                      
        at java.lang.Throwable.printStackTrace(java.base@11.0.14.1/Throwable.java:639)                     
        at io.grpc.servlet.web.websocket.WebSocketServerStream.onError(WebSocketServerStream.java:136)                                                                                                                
        at java.lang.invoke.DirectMethodHandle$Holder.invokeVirtual(java.base@11.0.14.1/DirectMethodHandle$Holder)                                                                                                    
        at java.lang.invoke.LambdaForm$MH/0x00000008006a6040.invoke(java.base@11.0.14.1/LambdaForm$MH)                                                                                                                
        at java.lang.invoke.LambdaForm$MH/0x00000008006ad040.invoke_MT(java.base@11.0.14.1/LambdaForm$MH)                                                                                                             
        at org.eclipse.jetty.websocket.jakarta.common.JakartaWebSocketFrameHandler.onError(JakartaWebSocketFrameHandler.java:312)                                                                                     
        at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.lambda$closeConnection$2(WebSocketCoreSession.java:283)                                                                                     
        at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession$$Lambda$831/0x00000008006d5840.run(Unknown Source)                                                                                          
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1460)                                                                                                                           
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1479)                                                                                                                           
        at org.eclipse.jetty.websocket.core.server.internal.AbstractHandshaker$1.handle(AbstractHandshaker.java:212)                                                                                                  
        at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.closeConnection(WebSocketCoreSession.java:283)                                                                                              
        at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.lambda$sendFrame$7(WebSocketCoreSession.java:518)                                                                                           
        at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession$$Lambda$989/0x0000000800800c40.run(Unknown Source)                                                                                          
        at org.eclipse.jetty.util.Callback$3.succeeded(Callback.java:155)                                  
        at org.eclipse.jetty.websocket.core.internal.TransformingFlusher.notifyCallbackSuccess(TransformingFlusher.java:151)                                                                                          
        at org.eclipse.jetty.websocket.core.internal.TransformingFlusher$Flusher.process(TransformingFlusher.java:111)                                                                                                
        at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:232)                                                                                                                            
        at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:214)                    
        at org.eclipse.jetty.websocket.core.internal.TransformingFlusher.sendFrame(TransformingFlusher.java:75)                                                                                                       
        at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.sendFrame(WebSocketCoreSession.java:521)                                                                                                    
        at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.close(WebSocketCoreSession.java:239)                                                                                                        
        at org.eclipse.jetty.websocket.core.internal.WebSocketCoreSession.processHandlerError(WebSocketCoreSession.java:370)                                                                                          
        at org.eclipse.jetty.websocket.core.internal.WebSocketConnection.onIdleExpired(WebSocketConnection.java:233)                                                                                                  
        at org.eclipse.jetty.io.AbstractEndPoint.onIdleExpired(AbstractEndPoint.java:407)                  
        at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:166)                         
        at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:108)                                
        at org.eclipse.jetty.io.IdleTimeout.activate(IdleTimeout.java:131)                                 
        at org.eclipse.jetty.io.IdleTimeout.setIdleTimeout(IdleTimeout.java:95)                            
        at org.eclipse.jetty.server.AbstractConnector.shutdown(AbstractConnector.java:390)                                                                                                                            
        at org.eclipse.jetty.server.AbstractNetworkConnector.shutdown(AbstractNetworkConnector.java:99)                                                                                                               
        at org.eclipse.jetty.util.component.Graceful$$Lambda$1664/0x0000000800b44c40.apply(Unknown Source)                                                                                                            
        at java.util.stream.ReferencePipeline$3$1.accept(java.base@11.0.14.1/ReferencePipeline.java:195)                                                                                                              
        at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(java.base@11.0.14.1/ArrayList.java:1655)                                                                                                         
        at java.util.stream.AbstractPipeline.copyInto(java.base@11.0.14.1/AbstractPipeline.java:484)                                                                                                                  
        at java.util.stream.AbstractPipeline.wrapAndCopyInto(java.base@11.0.14.1/AbstractPipeline.java:474)                                                                                                           
        at java.util.stream.AbstractPipeline.evaluate(java.base@11.0.14.1/AbstractPipeline.java:550)                                                                                                                  
        at java.util.stream.AbstractPipeline.evaluateToArrayNode(java.base@11.0.14.1/AbstractPipeline.java:260)                                                                                                       
        at java.util.stream.ReferencePipeline.toArray(java.base@11.0.14.1/ReferencePipeline.java:517)                                                                                                                 
        at org.eclipse.jetty.util.component.Graceful.shutdown(Graceful.java:146)                           
        at org.eclipse.jetty.server.Server.doStop(Server.java:489)                                         
        at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:132)                                                                                                                        
        at io.deephaven.server.jetty.JettyBackedGrpcServer.lambda$stopWithTimeout$1(JettyBackedGrpcServer.java:113)
        at io.deephaven.server.jetty.JettyBackedGrpcServer$$Lambda$1663/0x0000000800b44840.run(Unknown Source)                                                                                                        
        at java.lang.Thread.run(java.base@11.0.14.1/Thread.java:829)
        
    "Thread-0":
        at io.deephaven.io.logger.LogBuffer.record(LogBuffer.java:46)
        - waiting to lock <0x0000000082151358> (a io.deephaven.io.logger.LogBufferInterceptor)
        at io.deephaven.logback.LogBufferAppender.append(LogBufferAppender.java:57)
        at io.deephaven.logback.LogBufferAppender.append(LogBufferAppender.java:15)
        at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
        at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:50)
        at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:272)
        at ch.qos.logback.classic.Logger.callAppenders(Logger.java:259)
        at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:423)
        at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:385)
        at ch.qos.logback.classic.Logger.info(Logger.java:597)
        at io.deephaven.internal.log.LoggerSlf4j$Sink.write(LoggerSlf4j.java:156)
        at io.deephaven.internal.log.LoggerSlf4j$Sink.write(LoggerSlf4j.java:114)
        at io.deephaven.io.log.impl.LogEntryImpl.end(LogEntryImpl.java:78)
        at io.deephaven.internal.log.LoggerSlf4j$Entry.endl(LoggerSlf4j.java:99)
        at io.deephaven.server.barrage.BarrageMessageProducer.lambda$removeSubscription$6(BarrageMessageProducer.java:590)
        at io.deephaven.server.barrage.BarrageMessageProducer$$Lambda$986/0x0000000800800040.accept(Unknown Source)
        at io.deephaven.server.barrage.BarrageMessageProducer.lambda$findAndUpdateSubscription$2(BarrageMessageProducer.java:515)
        at io.deephaven.server.barrage.BarrageMessageProducer$$Lambda$987/0x0000000800800440.apply(Unknown Source)
        at io.deephaven.server.barrage.BarrageMessageProducer.findAndUpdateSubscription(BarrageMessageProducer.java:530)
        - locked <0x00000000bf85b390> (a io.deephaven.server.barrage.BarrageMessageProducer)
        at io.deephaven.server.barrage.BarrageMessageProducer.removeSubscription(BarrageMessageProducer.java:587)
        at io.deephaven.server.arrow.ArrowFlightUtil$DoExchangeMarshaller$SubscriptionRequestHandler.close(ArrowFlightUtil.java:705)
        at io.deephaven.server.arrow.ArrowFlightUtil$DoExchangeMarshaller.close(ArrowFlightUtil.java:443)
        at io.deephaven.server.session.SessionState.lambda$onExpired$0(SessionState.java:447)
        at io.deephaven.server.session.SessionState$$Lambda$1675/0x0000000800b47840.accept(Unknown Source)
        at io.deephaven.util.datastructures.SimpleReferenceManager.forEach(SimpleReferenceManager.java:121)
        at io.deephaven.server.session.SessionState.onExpired(SessionState.java:445)
        - locked <0x00000000864db808> (a io.deephaven.util.datastructures.SimpleReferenceManager)
        at io.deephaven.server.session.SessionService.closeAllSessions(SessionService.java:266)
        at io.deephaven.server.session.SessionService.onShutdown(SessionService.java:122)
        - locked <0x0000000082128b98> (a io.deephaven.server.session.SessionService)
        at io.deephaven.server.runner.DeephavenApiServer$$Lambda$264/0x0000000800320c40.invoke(Unknown Source)
        at io.deephaven.util.process.ShutdownManagerImpl.lambda$maybeInvokeTasks$2(ShutdownManagerImpl.java:108)
        at io.deephaven.util.process.ShutdownManagerImpl$$Lambda$1662/0x0000000800b44440.accept(Unknown Source)
        at java.util.Map.forEach(java.base@11.0.14.1/Map.java:661)
        at java.util.Collections$UnmodifiableMap.forEach(java.base@11.0.14.1/Collections.java:1505)
        at io.deephaven.util.process.ShutdownManagerImpl.maybeInvokeTasks(ShutdownManagerImpl.java:103)
        at io.deephaven.util.process.ShutdownManagerImpl$$Lambda$78/0x0000000800177440.run(Unknown Source)
        at java.lang.Thread.run(java.base@11.0.14.1/Thread.java:829)
@devinrsmith devinrsmith added bug Something isn't working triage labels Mar 10, 2022
@devinrsmith devinrsmith added this to the Mar 2022 milestone Mar 10, 2022
@devinrsmith devinrsmith changed the title Logging deadlock SimpleReferenceManager / Logging deadlock Mar 10, 2022
@rcaudy
Copy link
Member

rcaudy commented Mar 11, 2022

I think the right solution might be to off-thread the call to io.deephaven.server.session.SessionCloseableObserver#close at io.deephaven.server.console.ConsoleServiceGrpcImpl L475.
We want the session to be closed if it's not already in the process of closing, but best-effort is sufficient. Given that we might already be in the process of closing the session on another thread, we don't want to do this from inside the listener.

@rcaudy rcaudy assigned nbauernfeind and unassigned rcaudy Mar 11, 2022
@devinrsmith
Copy link
Member Author

I think the server crashing was exacerbated by the underlying #2087 bug; I don't have a good reproducer right now, but can potentially revert the app I'm working on (to explicitly trigger #2087) to see if that makes this easier to repro...

@devinrsmith
Copy link
Member Author

I've got a reproduction. The branch https://github.com/devinrsmith/deephaven-core/tree/issue-2086-reproducer is not explicitly meant as a reproducer (it was a fallout from some application development). None-the-less, it's pretty easy for me to repro:

./gradlew server-jetty:run -Pgroovy

After the server starts up (and starts application), Ctrl+C it.

At least 50% of the time, the app doesn't cleanly shut down. You can run jps to see if there are any JettyMain processes running. To get the stacktrace, do jstack <pid>. To cleanup the process, you'll need to kill -9 <pid>.

@pete-petey pete-petey modified the milestones: Mar 2022, May 2022 Apr 16, 2022
@nbauernfeind nbauernfeind mentioned this issue Jun 7, 2022
Closed
@nbauernfeind nbauernfeind modified the milestones: May 2022, Jun 2022 Jun 10, 2022
@nbauernfeind nbauernfeind mentioned this issue Jun 10, 2022
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@nbauernfeind nbauernfeind

Labels
bug Something isn't working console grpc jetty
Projects
None yet
Milestone
Jun 2022
4 participants
@nbauernfeind @rcaudy @devinrsmith @pete-petey