[issue40352] SocketHandler silently drops log messages on re-connect

[Oleg Nykolyn]

Oleg Nykolyn  added the comment:

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

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue40352] SocketHandler silently drops log messages on re-connect

[Vinay Sajip]

Vinay Sajip  added the comment:

@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)?

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue40352] SocketHandler silently drops log messages on re-connect

[Vinay Sajip]

Vinay Sajip  added the comment:

> 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.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue40352] SocketHandler silently drops log messages on re-connect

[Serhiy Storchaka]

Change by Serhiy Storchaka :


--
keywords: +patch
pull_requests: +21151
stage:  -> patch review
pull_request: https://github.com/python/cpython/pull/22061

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue40352] SocketHandler silently drops log messages on re-connect

[Serhiy Storchaka]

Serhiy Storchaka  added the comment:

In this particular case we do not need a buffer. It is enough to reopen the 
socket and send the current message again.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue40352] SocketHandler silently drops log messages on re-connect

[Vinay Sajip]

Vinay Sajip  added the comment:

> 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.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue40352] SocketHandler silently drops log messages on re-connect

[Serhiy Storchaka]

Serhiy Storchaka  added the comment:

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.

--
nosy: +serhiy.storchaka

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue40352] SocketHandler silently drops log messages on re-connect

[Rémi Lapeyre]

Rémi Lapeyre  added the comment:

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 `SocketHandler` very slow.

Maybe we could had the record to a very short queue so we can retry to send it 
with the next message?

--
nosy: +remi.lapeyre

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue40352] SocketHandler silently drops log messages on re-connect

[Serhiy Storchaka]

Change by Serhiy Storchaka :


--
nosy: +vinay.sajip

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue40352] SocketHandler silently drops log messages on re-connect

[Oleg Nykolyn]

New submission from Oleg Nykolyn :

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:

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.

--
components: Library (Lib)
files: Archive.zip
messages: 366920
nosy: Oleg Nykolyn
priority: normal
severity: normal
status: open
title: SocketHandler silently drops log messages on re-connect
type: behavior
versions: Python 3.8
Added file: https://bugs.python.org/file49080/Archive.zip

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com