Use simplified toString() implementation to avoid possible deadlocks

[turbanoff]

We got a deadlock in one of our applications

Found one Java-level deadlock:
=============================

"firebase-default-68":
  waiting for ownable synchronizer 0x00000000c8c01aa0, (a
java.util.concurrent.locks.ReentrantLock$NonfairSync),
  which is held by "httpclient-dispatch-1"

"httpclient-dispatch-1":
  waiting to lock monitor 0x00007f65a8009ae0 (object
0x00000000c1f1d5e0, a java.lang.Object),
  which is held by "firebase-default-68"

Java stack information for the threads listed above:
===================================================
"firebase-default-68":
at jdk.internal.misc.Unsafe.park(java.base@21.0.11/Native Method)
- parking to wait for  <0x00000000c8c01aa0> (a
java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(java.base@21.0.11/LockSupport.java:221)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@21.0.11/AbstractQueuedSynchronizer.java:788)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@21.0.11/AbstractQueuedSynchronizer.java:1024)
at java.util.concurrent.locks.ReentrantLock$Sync.lock(java.base@21.0.11/ReentrantLock.java:153)
at java.util.concurrent.locks.ReentrantLock.lock(java.base@21.0.11/ReentrantLock.java:322)
at org.apache.hc.core5.reactor.ssl.SSLIOSession.toString(SSLIOSession.java:903)
at org.apache.logging.log4j.message.ParameterFormatter.tryObjectToString(ParameterFormatter.java:600)
at org.apache.logging.log4j.message.ParameterFormatter.recursiveDeepToString(ParameterFormatter.java:450)
at org.apache.logging.log4j.message.ParameterFormatter.recursiveDeepToString(ParameterFormatter.java:419)
at org.apache.logging.log4j.message.ParameterFormatter.formatMessageContainingNoEscapes(ParameterFormatter.java:284)
at org.apache.logging.log4j.message.ParameterFormatter.formatMessage(ParameterFormatter.java:267)
at org.apache.logging.log4j.message.ReusableParameterizedMessage.formatTo(ReusableParameterizedMessage.java:351)
at org.apache.logging.log4j.core.async.RingBufferLogEvent.setMessage(RingBufferLogEvent.java:146)
at org.apache.logging.log4j.core.async.RingBufferLogEvent.setValues(RingBufferLogEvent.java:116)
at org.apache.logging.log4j.core.async.RingBufferLogEventTranslator.translateTo(RingBufferLogEventTranslator.java:60)
at org.apache.logging.log4j.core.async.RingBufferLogEventTranslator.translateTo(RingBufferLogEventTranslator.java:37)
at com.lmax.disruptor.RingBuffer.translateAndPublish(RingBuffer.java:962)
at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:466)
at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:331)
at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageWhenQueueFull(AsyncLoggerDisruptor.java:274)
- locked <0x00000000c1f1d5e0> (a java.lang.Object)
at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:291)
at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:275)
at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:270)
at org.apache.logging.log4j.core.async.AsyncLogger.access$000(AsyncLogger.java:70)
at org.apache.logging.log4j.core.async.AsyncLogger$1.log(AsyncLogger.java:177)
at org.apache.logging.log4j.core.async.AsyncLogger.log(AsyncLogger.java:148)
at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2904)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2857)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2839)
at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2629)
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2392)
at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:128)
at org.apache.hc.client5.http.impl.async.LoggingIOSession.enqueue(LoggingIOSession.java:83)
at org.apache.hc.core5.reactor.InternalDataChannel.enqueue(InternalDataChannel.java:286)
at org.apache.hc.client5.http.impl.nio.DefaultManagedAsyncClientConnection.submitCommand(DefaultManagedAsyncClientConnection.java:201)
at org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager$InternalConnectionEndpoint.execute(PoolingAsyncClientConnectionManager.java:765)
at org.apache.hc.client5.http.impl.async.InternalHttpAsyncExecRuntime.execute(InternalHttpAsyncExecRuntime.java:298)
at org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec.execute(HttpAsyncMainClientExec.java:295)
at org.apache.hc.client5.http.impl.async.AsyncExecChainElement.execute(AsyncExecChainElement.java:54)
at org.apache.hc.client5.http.impl.async.AsyncExecChainElement$$Lambda/0x00007f662cfd9680.proceed(Unknown
Source)
at org.apache.hc.client5.http.impl.async.AsyncConnectExec$1.completed(AsyncConnectExec.java:159)
at org.apache.hc.client5.http.impl.async.AsyncConnectExec$1.completed(AsyncConnectExec.java:153)
at org.apache.hc.client5.http.impl.async.InternalHttpAsyncExecRuntime$1.completed(InternalHttpAsyncExecRuntime.java:128)
at org.apache.hc.client5.http.impl.async.InternalHttpAsyncExecRuntime$1.completed(InternalHttpAsyncExecRuntime.java:120)
at org.apache.hc.core5.concurrent.BasicFuture.completed(BasicFuture.java:148)
at org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager$3$1.leaseCompleted(PoolingAsyncClientConnectionManager.java:342)
at org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager$3$1.completed(PoolingAsyncClientConnectionManager.java:324)
at org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager$3$1.completed(PoolingAsyncClientConnectionManager.java:289)
at org.apache.hc.core5.concurrent.BasicFuture.completed(BasicFuture.java:148)
at org.apache.hc.core5.pool.StrictConnPool.fireCallbacks(StrictConnPool.java:401)
at org.apache.hc.core5.pool.StrictConnPool.lease(StrictConnPool.java:219)
at org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager$3.<init>(PoolingAsyncClientConnectionManager.java:286)
at org.apache.hc.client5.http.impl.nio.PoolingAsyncClientConnectionManager.lease(PoolingAsyncClientConnectionManager.java:281)
at org.apache.hc.client5.http.impl.async.InternalHttpAsyncExecRuntime.acquireEndpoint(InternalHttpAsyncExecRuntime.java:115)
at org.apache.hc.client5.http.impl.async.AsyncConnectExec.execute(AsyncConnectExec.java:152)
at org.apache.hc.client5.http.impl.async.AsyncExecChainElement.execute(AsyncExecChainElement.java:54)
at org.apache.hc.client5.http.impl.async.AsyncExecChainElement$$Lambda/0x00007f662cfd9680.proceed(Unknown
Source)
at org.apache.hc.client5.http.impl.async.AsyncProtocolExec.internalExecute(AsyncProtocolExec.java:209)
at org.apache.hc.client5.http.impl.async.AsyncProtocolExec.execute(AsyncProtocolExec.java:174)
at org.apache.hc.client5.http.impl.async.AsyncExecChainElement.execute(AsyncExecChainElement.java:54)
at org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncClient$$Lambda/0x00007f662cfd8fd0.proceed(Unknown
Source)
at org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncClient.executeImmediate(InternalAbstractHttpAsyncClient.java:389)
at org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncClient.lambda$doExecute$0(InternalAbstractHttpAsyncClient.java:245)
at org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncClient$$Lambda/0x00007f662cfd2e30.sendRequest(Unknown
Source)
at org.apache.hc.core5.http.nio.support.BasicRequestProducer.sendRequest(BasicRequestProducer.java:93)
at org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncClient.doExecute(InternalAbstractHttpAsyncClient.java:209)
at org.apache.hc.client5.http.impl.async.CloseableHttpAsyncClient.execute(CloseableHttpAsyncClient.java:96)
at org.apache.hc.client5.http.impl.async.CloseableHttpAsyncClient.execute(CloseableHttpAsyncClient.java:106)
at org.apache.hc.client5.http.impl.async.CloseableHttpAsyncClient.execute(CloseableHttpAsyncClient.java:115)
at com.google.firebase.internal.ApacheHttp2Request.execute(ApacheHttp2Request.java:98)
at com.google.api.client.http.HttpRequest.execute(HttpRequest.java:1012)
at com.google.firebase.internal.ErrorHandlingHttpClient.send(ErrorHandlingHttpClient.java:97)
at com.google.firebase.internal.ErrorHandlingHttpClient.sendAndParse(ErrorHandlingHttpClient.java:72)
at com.google.firebase.messaging.FirebaseMessagingClientImpl.sendSingleRequest(FirebaseMessagingClientImpl.java:127)
at com.google.firebase.messaging.FirebaseMessagingClientImpl.send(FirebaseMessagingClientImpl.java:113)
at com.google.firebase.messaging.FirebaseMessaging$1.execute(FirebaseMessaging.java:142)
at com.google.firebase.messaging.FirebaseMessaging$1.execute(FirebaseMessaging.java:139)
at com.google.firebase.internal.CallableOperation.call(CallableOperation.java:36)
at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:131)
at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:75)
at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:82)


"httpclient-dispatch-1":
at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageWhenQueueFull(AsyncLoggerDisruptor.java:273)
- waiting to lock <0x00000000c1f1d5e0> (a java.lang.Object)
at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:291)
at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:275)
at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:270)
at org.apache.logging.log4j.core.async.AsyncLogger.access$000(AsyncLogger.java:70)
at org.apache.logging.log4j.core.async.AsyncLogger$1.log(AsyncLogger.java:177)
at org.apache.logging.log4j.core.async.AsyncLogger.log(AsyncLogger.java:148)
at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2904)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2857)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2839)
at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2646)
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:2413)
at org.apache.logging.slf4j.Log4jLogger.debug(Log4jLogger.java:123)
at org.apache.hc.client5.http.impl.async.LogAppendable.append(LogAppendable.java:63)
at org.apache.hc.client5.http.impl.async.LogAppendable.append(LogAppendable.java:55)
at org.apache.hc.client5.http.impl.async.LogAppendable.append(LogAppendable.java:49)
at org.apache.hc.core5.http2.frame.FramePrinter.printData(FramePrinter.java:209)
at org.apache.hc.core5.http2.frame.FramePrinter.printPayload(FramePrinter.java:174)
at org.apache.hc.client5.http.impl.async.HttpAsyncClientProtocolNegotiationStarter$2.logFramePayload(HttpAsyncClientProtocolNegotiationStarter.java:183)
at org.apache.hc.client5.http.impl.async.HttpAsyncClientProtocolNegotiationStarter$2.onFrameOutput(HttpAsyncClientProtocolNegotiationStarter.java:227)
at org.apache.hc.core5.http2.impl.nio.AbstractH2StreamMultiplexer.streamDataFrame(AbstractH2StreamMultiplexer.java:344)
at org.apache.hc.core5.http2.impl.nio.AbstractH2StreamMultiplexer.streamData(AbstractH2StreamMultiplexer.java:362)
at org.apache.hc.core5.http2.impl.nio.AbstractH2StreamMultiplexer.access$1200(AbstractH2StreamMultiplexer.java:98)
at org.apache.hc.core5.http2.impl.nio.AbstractH2StreamMultiplexer$H2StreamChannelImpl.write(AbstractH2StreamMultiplexer.java:1477)
at org.apache.hc.core5.http2.impl.nio.ClientH2StreamHandler$1.write(ClientH2StreamHandler.java:92)
at org.apache.hc.client5.http.impl.async.LoggingAsyncClientExchangeHandler$1.write(LoggingAsyncClientExchangeHandler.java:100)
at org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec$1$1.write(HttpAsyncMainClientExec.java:176)
at com.google.firebase.internal.ApacheHttp2AsyncEntityProducer.produce(ApacheHttp2AsyncEntityProducer.java:117)
at org.apache.hc.core5.http.nio.support.BasicRequestProducer.produce(BasicRequestProducer.java:104)
at org.apache.hc.client5.http.impl.async.InternalAbstractHttpAsyncClient$3.produce(InternalAbstractHttpAsyncClient.java:300)
at org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec$1.produce(HttpAsyncMainClientExec.java:167)
at org.apache.hc.client5.http.impl.async.LoggingAsyncClientExchangeHandler.produce(LoggingAsyncClientExchangeHandler.java:88)
at org.apache.hc.core5.http2.impl.nio.ClientH2StreamHandler.commitRequest(ClientH2StreamHandler.java:157)
at org.apache.hc.core5.http2.impl.nio.ClientH2StreamHandler.lambda$produceOutput$0(ClientH2StreamHandler.java:172)
at org.apache.hc.core5.http2.impl.nio.ClientH2StreamHandler$$Lambda/0x00007f662cffb878.sendRequest(Unknown
Source)
at org.apache.hc.client5.http.impl.async.LoggingAsyncClientExchangeHandler.lambda$produceRequest$0(LoggingAsyncClientExchangeHandler.java:74)
at org.apache.hc.client5.http.impl.async.LoggingAsyncClientExchangeHandler$$Lambda/0x00007f662cffbaa0.sendRequest(Unknown
Source)
at org.apache.hc.client5.http.impl.async.HttpAsyncMainClientExec$1.produceRequest(HttpAsyncMainClientExec.java:154)
at org.apache.hc.client5.http.impl.async.LoggingAsyncClientExchangeHandler.produceRequest(LoggingAsyncClientExchangeHandler.java:69)
at org.apache.hc.core5.http2.impl.nio.ClientH2StreamHandler.produceOutput(ClientH2StreamHandler.java:172)
at org.apache.hc.core5.http2.impl.nio.AbstractH2StreamMultiplexer$H2Stream.produceOutput(AbstractH2StreamMultiplexer.java:1675)
at org.apache.hc.core5.http2.impl.nio.AbstractH2StreamMultiplexer.processPendingCommands(AbstractH2StreamMultiplexer.java:654)
at org.apache.hc.core5.http2.impl.nio.AbstractH2StreamMultiplexer.onOutput(AbstractH2StreamMultiplexer.java:518)
at org.apache.hc.core5.http2.impl.nio.AbstractH2IOEventHandler.outputReady(AbstractH2IOEventHandler.java:74)
at org.apache.hc.core5.http2.impl.nio.ClientH2IOEventHandler.outputReady(ClientH2IOEventHandler.java:39)
at org.apache.hc.client5.http.impl.async.LoggingIOSession$1.outputReady(LoggingIOSession.java:243)
at org.apache.hc.core5.reactor.ssl.SSLIOSession.encryptData(SSLIOSession.java:658)
at org.apache.hc.core5.reactor.ssl.SSLIOSession.access$400(SSLIOSession.java:74)
at org.apache.hc.core5.reactor.ssl.SSLIOSession$1.outputReady(SSLIOSession.java:210)
at org.apache.hc.core5.reactor.InternalDataChannel.onIOEvent(InternalDataChannel.java:149)
at org.apache.hc.core5.reactor.InternalChannel.handleIOEvent(InternalChannel.java:51)
at org.apache.hc.core5.reactor.SingleCoreIOReactor.processEvents(SingleCoreIOReactor.java:176)
at org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(SingleCoreIOReactor.java:125)
at org.apache.hc.core5.reactor.AbstractSingleCoreIOReactor.execute(AbstractSingleCoreIOReactor.java:92)
at org.apache.hc.core5.reactor.IOReactorWorker.run(IOReactorWorker.java:44)

As you can see essential part of deadlock is SSLIOSession.toString() method which atempts to acuire the lock.
As a fix I propose to use tryLock instead and show only id+status when tryLock failed.
id is final in the main IOSession implementation - IOSessionImpl (shouldn't lead to any concurrency problems)
status is volatile enum field, so can be accessed without synchronization.

[ok2c]

@turbanoff Looks good to me. I have to say though #toString method should never get executed in normal circumstances in the productive mode, unless one explicitly turns on i/o session debug logging