Repository navigation
SocketHandler silently drops log messages on re-connect #84532
Description
Activity
OlegNykolyn commented
on Apr 21, 2020 OlegNykolynmannequinMannequinAuthorHi,
I've faced this issue when using logging.handlers.SocketHandler AWS TCP balancer. AWS balancer uses 60 second time-out by default (max 4000s), thus resulting in lots of closed sockets during inactive periods.
SocketHandler.send() drops current message on any socket errors, so only next message gets logged.
I've tried to reproduce this using Lib unit tests, but didn't find any easy way to close() socket on test server side.Sample client/server scripts attached, server output:
Got connection from: ('127.0.0.1', 58044) Got message: b'Message #1\n' Got message: b'Message #2\n' Got connection from: ('127.0.0.1', 58045) Got message: b'Message #5\n'Server closes incoming connection is 2 seconds, client looses messages #3 and #4.
remilapeyre commented
on Apr 21, 2020 remilapeyremannequinMannequinOn one hand it's bad messages get lost, one the other retrying to send the message would take a lot of time and make
SocketHandlervery slow.Maybe we could had the record to a very short queue so we can retry to send it with the next message?
If sending log messages is not guaranteed, we could use UDP. But when we use TCP it is expected that log messages will not be lost.
But when we use TCP it is expected that log messages will not be lost.
I wouldn't go that far: logging is not a primary program function (i.e. the library or application should work exactly the same if logging were to be disabled). For the situation where you absolutely don't want to lose messages (apparently not that common a case - the relevant code is over 15 years old, and I can't remember this coming up before), you could either subclass SocketHandler to buffer messages, or use e.g. a MemoryHandler in conjunction with a SocketHandler.
In this particular case we do not need a buffer. It is enough to reopen the socket and send the current message again.
It is enough to reopen the socket and send the current message again.
A common reason for connection failure in SocketHandler is the other end going offline for some reason. The offline period can often be measured in seconds to hours, or even longer. The current strategy is to retry connection, but on the next logging call, and with an exponential backoff.
Otherwise, if the remote end goes down and you keep retrying to connect on the same call, the handler would keep trying to connect and failing, and this could slow things down.
@oleg In the interests of clarity, can you please give more detail about the network topology and sequence of events in your use case? Where the machine with the SocketHandler is, where the socket server is that it's sending to, where the TCP balancer comes into it, what exactly the timeout is for, and what is the precise cause of the socket errors {e.g. whether a failure occurs after a connection has been made and some events have been successfully logged - if so, what exactly causes the failure)?
OlegNykolyn commented
on Oct 14, 2020 OlegNykolynmannequinMannequinAuthorThere are multiple servers running in Kubrnetes cluster - API servers based on Django, celery workers, etc. All of them send logs to AWS TCP balancer, which acts as balancer for vector service[1], which send logs to Elasticsearch.
Basically we have following logging pipeline: python-based services -> AWS TCP network balancer -> vector -> Elasticsearch.
AWS network balancer has an option called "Idle timeout" with max value of 3600 seconds[2].
Log messages are logged successfully at first, but fail(one message gets lost on re-connect) if there is gap between messages, corresponding to "Idle timeout".1: https://github.com/timberio/vector
2: https://docs.aws.amazon.com/elasticloadbalancing/latest/network/network-load-balancers.html#connection-idle-timeoutHmmm. I set up a slightly modified version of these test files here [and a Gist is here], and I am seeing something odd: If I run
python t_server.py &followed bypython t_client.py, I get output like this:39891.620592 Client trying to create socket 39891.628369 Client created socket 39891.628408 Client sending b'Message #1\n' 39891.628437 Client sent b'Message #1\n' 39891.628479 Server got connection from: ('127.0.0.1', 35584) 39891.628601 Server got message: b'Message #1\n' 39896.633251 Client sending b'Message #2\n' 39896.633459 Client sent b'Message #2\n' 39896.633532 Server got message: b'Message #2\n' 39896.633681 Server shut down reading on socket 39896.633770 Server closed socket 39896.838884 Client sending b'Message #3\n' 39896.839071 Client sent b'Message #3\n' 39897.039539 Client sending b'Message #4\n' 39897.039638 Client failed to send b'Message #4\n' ([Errno 32] Broken pipe) 39897.240175 Client trying to create socket 39897.240500 Client created socket 39897.240542 Client sending b'Message #5\n' 39897.240579 Client sent b'Message #5\n' 39897.240770 Server got connection from: ('127.0.0.1', 43562) 39897.240893 Server got message: b'Message #5\n'What I find odd is that the server closes its socket before the client sends Message 3, but no error is seen at the socket level until Message 4 is sent. I can't at the moment see why that is - I would have expected to see a "failed to send" for Message 3.
Pinging @nykolynoleg in case you are the OP for this issue.
OK, I think I see why Message 3 didn't raise an error - it was buffered locally and an actual attempt send only happened when Message 4 was sent. At that point the fact that the server had gone away was detected. If you want to avoid this problem you will probably need to use UDP, even though it is lossy. In a stream-oriented protocol, events could be buffered up locally in a network buffer (with no way of knowing which ones have actually been sent to the server).
Yes, this was the problem I encountered when trying to write the tests. This is why #22061 was not finished. Maybe there is some way to save the local buffer and resend it after reconnecting?
Not without peeking into lower levels of the socket code, I don't think. It might also expose the user to low-level details of TCP (windows, flow control etc.) which is probably not desirable to do. The basic problem is that the OP wants to treat logging events discretely, implying datagrams, but to do it over the streaming interface of TCP. What would be needed would be a socket
flush()method which flushed the current contents of the client's network buffer to the server. If that were available (of course, it isn't), we could force the buffer to be sent to the server by callingflush()fromemit(), and that would detect the error straight away where the event was still available as aLogRecordwhich could be buffered to be sent later.Relevant: an answer to the question How can I force a socket to send the data in its buffer? - tl;dr:
You can't force it. Period.
Then we have no choice but to close this issue?
I would like to reopen this.
SocketHandlercannot be made lossless over TCP -- the first record after the connection is closed is lost locally before the reset arrives, and I am not proposing to fix that.But two records are lost here, not one. In the OP's log #3 is that unavoidable one, while #4 fails with
BrokenPipeErrorandsend()simply drops it, reconnecting only on the next record. Resending #4 instead is not a new policy:SysLogHandlerhas reopened the socket and resent the current record onOSErrorsince 2.5.The other reason #22061 stalled was the lack of a faithful test. That is now solved. See #154540.
Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.
Show more details
GitHub fields:
bugs.python.org fields:
Linked PRs