Can Python logging SMTP Handler freeze my stream for 2 minutes?
A rather complicated sequence of events happened according to my log file, and I'm going to put a lot of blame on the Python logger, which is a bold claim. I thought I should get a second opinion on whether what I am talking about might be.
I am trying to explain why there are several large gaps in my log file (about two minutes at a time) during stressful periods for my application when it is running out of time.
I am using the Python logging module on a remote server and have a config with a config file for all logs with ERROR severity or higher to email me. Typically only one error is sent at a time, but during periods of prolonged problems I can get a dozen minutes - annoying, but it doesn't cost anything to underline SMTP.
I find that after a short propagation of such messages, the Python protocol system (or perhaps the SMTP system it sits on) is experiencing errors or overloads. The Python log call is then LOCKED for two minutes, causing my thread to miss its deadlines. (I was smart enough to move the log to the application's critical path - so I don't care if the log takes a few seconds, but two minutes is too long.)
This seems like a rather awkward architecture (both for a logging system that can freeze up and an SMTP system (Ubuntu, sendmail) that can't handle tens of emails per minute **), so it surprises me, but it matches the symptoms exactly.
Anyone have any experience? Can anyone describe how to stop it from blocking?
** EDIT # 2: I really believed. 170 letters in two hours. Forget about previous edits. I thought it was wrong. It's late here ...
a source to share
Stress testing showed:
My logging configuration sent critical messages to the SMTPHandler and debugs messages in the local log file.
For testing purposes, I created a moderately large number of threads (50 for example) that were waiting for a trigger and then simultaneously tried to log a critical or debug message depending on the test.
Test # 1: All Threads Send Critical Messages: It showed that the first critical message took about 0.9 seconds to send. The second critical message took about 1.9 seconds to send. The third is even longer, folding quickly. It seems that the messages that go to the email block are waiting for each other to complete sending.
Test # 2: all threads send debug messages: they ran pretty fast, from hundreds to thousands of microseconds.
Test # 3: a combination of both. It was clear from the results that debug messages are also blocked pending critical messages.
So it wasn't that 2 minutes meant there was a timeout. It was exactly two minutes that represented a large number of threads blocked in a queue in a queue.
Why were so many critical messages sent at once? It's irony. There was a call to logging.debug () inside a method that included a network call. I had some code to control the speed of the method (to see if the network call is too long). If so, he (of course) logged a critical bug that sent the email. The next thread is then blocked when logging.debug () is called, which means it missed the deadline by calling another email, starting another thread to start slowly.
The 2 minute delay in one thread was not a network timeout. It was one thread waiting for another thread that was blocked for 1 minute 57 - because it was waiting for another thread to be blocked for 1 minute 55, etc. Etc. Etc.
This is not very nice behavior from SMTPHandler.
a source to share