Repository navigation
SocketHandler silently drops log messages on re-connect #84532
Description
| BPO | 40352 |
|---|---|
| Nosy | @vsajip, @serhiy-storchaka, @remilapeyre |
| PRs | |
| Files |
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:
assignee = None
closed_at = None
created_at = <Date 2020-04-21.13:02:07.496>
labels = ['3.8', 'type-bug', 'library']
title = 'SocketHandler silently drops log messages on re-connect'
updated_at = <Date 2020-10-14.15:36:25.488>
user = 'https://bugs.python.org/OlegNykolyn'bugs.python.org fields:
activity = <Date 2020-10-14.15:36:25.488>
actor = 'Oleg Nykolyn'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2020-04-21.13:02:07.496>
creator = 'Oleg Nykolyn'
dependencies = []
files = ['49080']
hgrepos = []
issue_num = 40352
keywords = ['patch']
message_count = 8.0
messages = ['366920', '366925', '366929', '376190', '376217', '376229', '376844', '378625']
nosy_count = 4.0
nosy_names = ['vinay.sajip', 'serhiy.storchaka', 'remi.lapeyre', 'Oleg Nykolyn']
pr_nums = ['22061']
priority = 'normal'
resolution = None
stage = 'patch review'
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue40352'
versions = ['Python 3.8']
Activity
OlegNykolyn commentedon Apr 21, 2020
Hi,
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:
Server closes incoming connection is 2 seconds, client looses messages #3 and #4.
remilapeyre commentedon Apr 21, 2020
On 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?
serhiy-storchaka commentedon Apr 21, 2020
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.
vsajip commentedon Sep 1, 2020
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.
serhiy-storchaka commentedon Sep 2, 2020
In this particular case we do not need a buffer. It is enough to reopen the socket and send the current message again.
vsajip commentedon Sep 2, 2020
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.
vsajip commentedon Sep 13, 2020
@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 commentedon Oct 14, 2020
There 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-timeout
vsajip commentedon Oct 3, 2022
Hmmm. 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: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.
vsajip commentedon Oct 3, 2022
Pinging @nykolynoleg in case you are the OP for this issue.
vsajip commentedon Oct 3, 2022
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).
serhiy-storchaka commentedon Oct 3, 2022
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?
vsajip commentedon Oct 3, 2022
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.vsajip commentedon Oct 5, 2022
Relevant: an answer to the question How can I force a socket to send the data in its buffer? - tl;dr:
serhiy-storchaka commentedon Oct 5, 2022
Then we have no choice but to close this issue?
vsajip commentedon Oct 5, 2022
I think so 😞 and it would seem that #22061 will need to be closed, too.
serhiy-storchaka commentedon Jul 23, 2026
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.
pythongh-84532: Close the accepted connections in test_reconnect