NetworkTarget with TCP KeepConnection=true should retry on error

[MikeFH]

When using the NetworkTarget with the KeepConnection=true, the connection to the server is kept open so that it can be reused. Using the TCP protocol, if the server is configured to close the connection after a period of inactivity (a common configuration to avoid DOS), we then have a NetworkSender holding a closed Socket. The problem is that it seems that the next log message we try to send will not be received by the server (executing https://github.com/NLog/NLog/blob/master/src/NLog/Targets/NetworkTarget.cs#L291).

One workaround would be to set KeepConnection=false but in case of a TCP connection this can be expensive when the application starts to write more logs.
Another solution would be to use RetryingTargetWrapper, but it seems a bit odd to configure a retry for that particular case since no error really occurred.

So do you think it is possible to check the status of the socket before using it to send the message and try to open a new one in case it was cleanly closed by the server ?

[snakefoot]

I guess it would make sense for the KeepConnection=true situation, that if the Socket has been used successfully before, then the target should perform an implicit connection-retry before doing hard failure.

Pull Requests are welcome.

[304NotModified]

That would be a nice feature to add. PR would be great indeed!

[snakefoot]

Created NLog/NLog#3124 to allow faster detection of broken socket connections.

Probably need some extra logic to perform a zero-byte Send-call before using an existing socket:

https://docs.microsoft.com/en-us/dotnet/api/system.net.sockets.socket.connected#examples

[martinmine]

This is actually pretty bad. If the TCP connection gets closed (this can be quite normal), NLog has no internal mechanism for observing that the connection has been gracefully closed. In these cases, .NET fires the callback handler for received data with 0 received bytes. NLog has no such implementation. I will see if I can try and write a patch for this in the near future.

[snakefoot]

@martinmine You are more than welcome to create a PR. Maybe make it so you only perform the connection-check when socket has been unused for X seconds (Default Check Disabled = -1, Check Always = 0)

[304NotModified]

. I will see if I can try and write a patch for this in the near future

That would be great 👍

[martinmine]

@snakefoot I wasn't thinking of performing any connection checking, but simply add support for listening for the connection to be gracefully closed. All in all, I simply register a receive handler and if that handler received 0 bytes, the connection gets marked as closed.

[snakefoot]

@martinmine Like this: https://stackoverflow.com/a/53315852/193178 (Sync) ? or like this https://stackoverflow.com/a/32244584/193178 + https://stackoverflow.com/a/2015520/193178 (Async) ?

[martinmine]

@snakefoot Actually, neither. I don't want to mess with any socket parameters since I want to get a general solution to this problem. Different systems (routers/endpoints/whatever) may act differently with the keep-alive flag for example, and the root cause of this problem is lack of error-handling which is what I want to improve. Give me a few hours and I might have something going on a proof-of-concept branch :)

[snakefoot]

@martinmine Been able to decipher the NLog-code for NetworkTarget? Or maybe it is easier for you to present your idea as sample-code here in this issue?

[martinmine]

@snakefoot Sorry for the delay, got quite busy the past few days ... :( I've managed to scramble something together, I haven't tested it out but I think it's a start: NLog/NLog@39d39cf

[snakefoot]

@martinmine Ok so you are doing an Async-Receive and if it completes with no data returned, then you see the connection as broken. Just like the stackoverflow-articles are doing.

Some of the stackoverflow-articles improve on this logic by enabling socket-KeepAlive, so they will react to network-cable disconnect (and not just correct socket-close-handshake). But I also think it is a good idea to these two features separate.

But I guess some logic is needed for better handling of _pendingRequests. Maybe instead of closing the socket and throwing it all away, then maybe try reconnect first?

[martinmine]

@snakefoot I don't see any reason implementing it synchronous as the APIs being used in NLog are asynchronous. I went a bit back and forth with how to approach it since I haven't used this specific async API on the Socket API, but it also had to fit in the context NLog use it.

I agree it would make sense to implement these two separately (imo gracefully handling socket closing is a bare minimum). I don't think attempting to reconnect would be appropriate. Let's say the connection gets closed on the server due to inactivity. It would appear odd if NLog would just open connections that don't send any data. The reason I close it at this stage (_pendingRequests) is that I don't have a way of signaling to the NetworkTarget class when the close event fires. Since a socket connection is this tightly coupled (the properties in the NetworkSender and TcpNetworkSender class reflects much of the current socket state) with how the class is written, I would argue it is more reasonable to throw it away.

[snakefoot]

It would appear odd if NLog would just open connections that don't send any data.

Well lets try this story with your new logic:

1. NetworkTarget sends 100 LogEvent to address IPA (Creates NetworkSender etc.)
2. NetworkSender enters a disconnected state after having sent 50 LogEvents (Still 50 events in pending-queue)
3. NetworkTarget sends 100 new LogEvent to address IPA (Lookup NetworkSender and sees not connected and disconnect, and then creates new NetworkSender to same address).

Now we have lost 50 LogEvents. And the NetworkTarget will happily reconnect anyway on the next batch. I understand it would not make sense to reconnect when not having anything to send. But when having items in pending-queue then it would be "smart" with simple retry mechanism with randomly-growing-retry-delay.