Why does this need to be logged when the level is set to ERROR?

bashkim · August 14, 2024, 1:06am

The server logs this non-stop. If this is a problem then it should be looked after.

If it is not then it should not be logged because it obviously does nothing good and only wears off our drives.

I’ll repeat:
TRACE: Log everything you can
DEBUG: Log stack traces from warnings and errors
INFO: Log additional information about BAU operation, warnings, and errors
WARNING: Log warnings and errors
ERROR: Log errors
CRITICAL: Log only critical errors.

When you flood logs with stack traces that no one is interested in you only cause confusion and run up SSD write counts unnecessarily.

2024.08.13 19:46:50.529 e[1;31mERRORe[m [socket_c2s-thread-6]: org.jivesoftware.openfire.nio.NettyConnection - Problem during connection close or cleanup
io.netty.channel.StacklessClosedChannelException: null
	at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
Caused by: java.io.IOException: An established connection was aborted by the software in your host machine
	at sun.nio.ch.SocketDispatcher.write0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:54) ~[?:?]
	at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:132) ~[?:?]
	at sun.nio.ch.IOUtil.write(IOUtil.java:76) ~[?:?]
	at sun.nio.ch.IOUtil.write(IOUtil.java:53) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:532) ~[?:?]
	at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:415) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:931) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:895) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1372) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:921) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:907) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:893) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.ssl.SslHandler.forceFlush(SslHandler.java:2236) ~[netty-handler-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.ssl.SslHandler.wrapAndFlush(SslHandler.java:825) ~[netty-handler-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.ssl.SslHandler.flush(SslHandler.java:802) ~[netty-handler-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:925) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:907) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:893) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.ChannelOutboundHandlerAdapter.flush(ChannelOutboundHandlerAdapter.java:125) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:925) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:941) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:966) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:934) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:984) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at org.jivesoftware.openfire.nio.NettyConnection.deliverRawText(NettyConnection.java:328) ~[xmppserver-4.8.1.jar:4.8.1]
	at org.jivesoftware.openfire.session.LocalSession.deliverRawText(LocalSession.java:465) [xmppserver-4.8.1.jar:4.8.1]
	at org.jivesoftware.openfire.streammanagement.StreamManager.sendServerAcknowledgement(StreamManager.java:405) ~[xmppserver-4.8.1.jar:4.8.1]
	at org.jivesoftware.openfire.streammanagement.StreamManager.process(StreamManager.java:195) ~[xmppserver-4.8.1.jar:4.8.1]
	at org.jivesoftware.openfire.net.StanzaHandler.processStanza(StanzaHandler.java:219) [xmppserver-4.8.1.jar:4.8.1]
	at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:114) [xmppserver-4.8.1.jar:4.8.1]
	at org.jivesoftware.openfire.nio.NettyConnectionHandler.channelRead0(NettyConnectionHandler.java:142) [xmppserver-4.8.1.jar:4.8.1]
	at org.jivesoftware.openfire.nio.NettyConnectionHandler.channelRead0(NettyConnectionHandler.java:50) [xmppserver-4.8.1.jar:4.8.1]
	at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346) [netty-codec-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318) [netty-codec-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) [netty-handler-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.traffic.AbstractTrafficShapingHandler.channelRead(AbstractTrafficShapingHandler.java:506) [netty-handler-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1471) [netty-handler-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1334) [netty-handler-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1383) [netty-handler-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:529) [netty-codec-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:468) [netty-codec-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:290) [netty-codec-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) [netty-transport-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) [netty-common-4.1.100.Final.jar:4.1.100.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.100.Final.jar:4.1.100.Final]
	at java.lang.Thread.run(Thread.java:833) [?:?]

Gregory_Young · November 27, 2024, 6:40pm

You might have your server set to debug as I am not getting the stack traces with a similar error. My Openfire logs are set to INFO and the ‘org.eclipse.jetty’ entries are set to warn.

2024-11-27T18:03:06.398Z ^[[1;31mERROR^[[m [nioEventLoopGroup-3-1]: org.jivesoftware.openfire.nio.NettyConnection - Problem during connection close or cleanup
io.netty.channel.StacklessClosedChannelException: null
        at io.netty.channel.AbstractChannel$AbstractUnsafe.write(Object, ChannelPromise)(Unknown Source) ~[netty-transport-4.1.100.Final.jar:4.1.100.Final]
2024-11-27T18:05:10.854Z ^[[1;31mERROR^[[m [nioEventLoopGroup-3-2]: org.jivesoftware.openfire.nio.NettyConnection - Problem during connection close or cleanup
io.netty.channel.StacklessClosedChannelException: null

All of that said, I would love to know the cause of this issue. We are doing an OS upgrade which includes moving to Java 21, so we upgraded to 4.8.0. At the same time we put Openfire BOSH behind an Envoy reverse proxy (we previously did this with a proxy URL on port 443, but now we are also forwarding port 5280 as well). Yes we have ‘httpbind.forwarded.enabled’ enabled and the required headers in place.

guus · November 27, 2024, 7:08pm

Much of these messages (that contain the text “Problem during connection close or cleanup” should not be logged on level ERROR, for the reasons mentioned by @bashkim : they are confusing.

There are a couple of different error conditions that get logged incorrectly like this. The reason for that is a bug in Openfire. The exceptional condition is not caught by the code that was expected to catch it. Instead, it is caught elsewhere. As on that location, this exception was unexpected, it is logged verbosely on level ERROR.

I’ve been looking at this in context of ticket OF-2914, but I’ve not yet been able to put my finger on the underlying cause.

Note that Openfire correctly identifies an erroneous state, and functionally does what it should do (close/clean up the connection). It is the logging that is not quite right.

guus · November 27, 2024, 7:10pm

4.8.0 has known defects. Please consider upgrading to the latest release (which is 4.9.2 at the time of writing).

Gregory_Young · November 27, 2024, 7:40pm

I’m in the process of building it now.