Allow connection error logging to be overridden

[TheWizz]

I'm getting quite some error messages in my log like the one below. unfortunately, there seem to be no way of controlling what gets logged and how (unless I'm overlooking something), since this is hard-coded into ModbusTcpMaster::onExceptionCaught, which is a private function. While I understand that the handling of the error mush happen here (e.g., to call failPendingRequests and ctx.close), it would be nice to have an extension point for how this is treated as far as logging is concerned. I would prefer to NOT log this particular issue (i.e., the "other end" closing the connection) as an Error (perhaps I'd log it as a warning, or not at all, since it's rather benign and almost "normal").

Perhaps a protected method could be added, called from onExceptionCaught, where the default implementation is what you do now:

       logger.error("Exception caught: {}", cause.getMessage(), cause);

but allowing me to handle this in some other way for select exceptions (such as this "Connection reset by peer" case). Or perhaps there's some better way to get control over this behavior, avoiding polluting my log file with scary-lookin ERRORs for such rather benign occurences.

-JM

ERROR [2017-06-21 09:10:03,026] com.digitalpetri.modbus.master.ModbusTcpMaster: Exception caught: Connection reset by peer
! java.io.IOException: Connection reset by peer
! at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
! at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
! at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
! at sun.nio.ch.IOUtil.read(IOUtil.java:192)
! at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
! at io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:288)
! at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1100)
! at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:366)
! at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:118)
! at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:642)
! at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:565)
! at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:479)
! at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:441)
! at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
! at java.lang.Thread.run(Thread.java:745)

[kevinherron]

I see how that could be annoying.

A couple approaches I could take:

1. Log on DEBUG by default and start tracking and incrementing another counter.
2. Make it protected allowing you to subclass and override that onExceptionCaught.

Option 1 is somewhat flawed in that the counter would be for all exceptions caught, not just the case where the peer disconnects.

Option 2 is somewhat flawed in that your override would need to know to clear pending requests and call ctx.close().

[TheWizz]

My idea was to create another function that does ONLY the logging; i.e., this line

logger.error("Exception caught: {}", cause.getMessage(), cause);

That function would be protected, rather than private, with a default implementation just as shown above. The current (private) function would call this, and then clear pending requests and call ctx.close, which I understand is important (and is an internal detail any derived class should be oblivious to). I could then override that "exception logging" function, and log this in a "less agressive" way, or perhaps not at all if I consider this particular error "normal" (which I guess it is, since the modbus TCP connection is often closed down after some time of inactivity). Something like this:

    private void onExceptionCaught(ChannelHandlerContext ctx, Throwable cause) throws Exception {
        logOnExceptionCaught(cause);
        failPendingRequests(cause);
        ctx.close();
    }

    protected void logOnExceptionCaught(Throwable cause) {
        logger.error("Exception caught: {}", cause.getMessage(), cause);
    }

[TheWizz]

Any update or other suggestions here on how to suppress these rather annoying error messages in my log?

[kevinherron]

Whoa, been a while on this one. I think it should just be logged on DEBUG level. If you want to submit a PR that changes it I'll merge it, otherwise I'll try and remember to do it tonight.

[kevinherron]

Changed this. I'll cut a release soon-ish.

[TheWizz]

Thanks! Your change will certainly accomplish what I want.

However, it also stands the chance of masking some more "interesting" exceptions than "Connection reset by peer". Hence my suggestion with logging through a protected function, keeping today's behavior intact as default, but allowing a subclass to then override the logging behavior in certain cases (such as this "Connection reset by peer" case, which is presumably caused by the other end of the wire).

[kevinherron]

You've had it on ERROR level in production for a while - have you ever actually seen another exception occur?

[TheWizz]

No, not under normal operation. However, the interesting things to get in the log are the *abnormal* events. So I fear that by dropping this to DEBUG across the board, some REAL erro rmay fall between the cracks, rather than being logged. So by making the way this is actually logged overridable the way I suggest, that decision can be pushed down into a subclass, while keeping the default behavior as it is today. That subclass could then for example log all those errors using DEBUG (as you do now with your latest change), or take a closer look at the actual exception, and make decisions on what to log with finer granularity (or even take other actions than loggin here, within reason of course).

…

-JM

[kevinherron]

Okay, how does #18 look?

It's a little awkward to me because nothing else about ModbusTcpMaster is designed to be subclassed, and I don't really intend to change that, but the only alternative is passing in some kind of Function to handle logging behavior via the config object and that seems not that great either.

[TheWizz]

Looks fine to me. Possibly I would instead do logger.error here, as shown below, since it is safer (all exceptions are logged as errors by default) and would do the same as your previous implementation (least surprise). Since it's now possible to override, either way is fine by me, though.

…

-JM protected void onExceptionCaught(ChannelHandlerContext ctx, Throwable cause) { logger.error("Exception caught: {}", cause.getMessage(), cause); }

[kevinherron]

I've just done the release, version 1.1.1 should be available in Maven soon-ish.

[TheWizz]

Many thanks!

…

-JM