Skip to content

[pulsar-websocket] Do not log stack trace with warn log in websocket proxy#4945

Merged
nkurihar merged 1 commit intoapache:masterfrom
massakam:ws-warn-log
Aug 14, 2019
Merged

[pulsar-websocket] Do not log stack trace with warn log in websocket proxy#4945
nkurihar merged 1 commit intoapache:masterfrom
massakam:ws-warn-log

Conversation

@massakam
Copy link
Contributor

Motivation

The other day, the disk of one of our websocket proxy became full. This was because the following stack trace was repeatedly output and the log file became very large.

17:05:24.942 [pulsar-websocket-web-1-9] WARN  o.a.pulsar.websocket.ProducerHandler - [persistent://xxx/global/yyy/zzz] Failed to send ack Connection has been closed locally
java.io.EOFException: Connection has been closed locally
        at org.eclipse.jetty.websocket.common.io.FrameFlusher.close(FrameFlusher.java:317)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.disconnect(AbstractWebSocketConnection.java:305)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.access$300(AbstractWebSocketConnection.java:61)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$OnDisconnectCallback.writeFailed(AbstractWebSocketConnection.java:101)
        at org.eclipse.jetty.websocket.common.io.FrameFlusher.notifyCallbackFailure(FrameFlusher.java:391)
        at org.eclipse.jetty.websocket.common.io.FrameFlusher.enqueue(FrameFlusher.java:344)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.outgoingFrame(AbstractWebSocketConnection.java:614)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onConnectionStateChange(AbstractWebSocketConnection.java:473)
        at org.eclipse.jetty.websocket.common.io.IOState.notifyStateListeners(IOState.java:184)
        at org.eclipse.jetty.websocket.common.io.IOState.onWriteFailure(IOState.java:548)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher.onFailure(AbstractWebSocketConnection.java:85)
        at org.eclipse.jetty.websocket.common.io.FrameFlusher$Flusher.onCompleteFailure(FrameFlusher.java:109)
        at org.eclipse.jetty.util.IteratingCallback.failed(IteratingCallback.java:401)
        at org.eclipse.jetty.io.WriteFlusher$PendingState.fail(WriteFlusher.java:260)
        at org.eclipse.jetty.io.WriteFlusher.onFail(WriteFlusher.java:482)
        at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint$1$1.failed(SslConnection.java:327)
        at org.eclipse.jetty.io.AbstractConnection$1.run(AbstractConnection.java:115)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)
17:05:24.942 [pulsar-client-io-5-2] WARN  o.a.pulsar.websocket.ProducerHandler - [persistent://xxx/global/yyy/zzz] Failed to send ack RemoteEndpoint unavailable, current state [CLOSED], expecting [OPEN or CONNECTED]
org.eclipse.jetty.websocket.api.WebSocketException: RemoteEndpoint unavailable, current state [CLOSED], expecting [OPEN or CONNECTED]
        at org.eclipse.jetty.websocket.common.WebSocketSession.getRemote(WebSocketSession.java:308)
        at org.apache.pulsar.websocket.ProducerHandler.sendAckResponse(ProducerHandler.java:247)
        at org.apache.pulsar.websocket.ProducerHandler.lambda$onWebSocketText$2(ProducerHandler.java:198)
        at java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:656)
        at java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:632)
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
        at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
        at org.apache.pulsar.client.impl.ProducerImpl$1.sendComplete(ProducerImpl.java:247)
        at org.apache.pulsar.client.impl.ProducerImpl.ackReceived(ProducerImpl.java:702)
        at org.apache.pulsar.client.impl.ClientCnx.handleSendReceipt(ClientCnx.java:281)
        at org.apache.pulsar.common.api.PulsarDecoder.channelRead(PulsarDecoder.java:196)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:310)
        at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:297)
        at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:413)
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
        at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1389)
        at io.netty.handler.ssl.SslHandler.decodeNonJdkCompatible(SslHandler.java:1171)
        at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1205)
        at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:489)
        at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:428)
        at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
        at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
        at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1414)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
        at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:945)
        at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:806)
        at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:404)
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:304)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:748)

I don't think it's necessary to output a stack trace with the warn log. It would be enough to output the message contained in the exception object.

Modifications

Modified ProducerHandler class so that stack trace is not output with warn logs.

@massakam massakam added this to the 2.5.0 milestone Aug 13, 2019
@massakam massakam self-assigned this Aug 13, 2019
@massakam
Copy link
Contributor Author

rerun cpp tests

@nkurihar nkurihar merged commit 88e6b2b into apache:master Aug 14, 2019
@massakam massakam deleted the ws-warn-log branch September 15, 2019 15:36
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants