classification
Title: logging smtp handler (and test) timeout issue
Type: behavior Stage: resolved
Components: Library (Lib) Versions: Python 3.2, Python 3.3, Python 2.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: vinay.sajip Nosy List: python-dev, r.david.murray, vinay.sajip
Priority: normal Keywords: easy

Created on 2012-03-15 04:59 by r.david.murray, last changed 2012-03-23 14:38 by python-dev. This issue is now closed.

Messages (4)
msg155858 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2012-03-15 04:59
I'm working on a patch that updates smtpd, and when I ran the full test suite I got a hang in test_logging.  This means there's a bug in my update, but there is also a bug in the logging test.

But see below for another issue I noticed while investigating this, that is the real focus of this report.

This traceback occurs before the test hang:

test_basic (test.test_logging.SMTPHandlerTest) ... error: uncaptured python exception, closing channel <test.test_logging.TestSMTPChannel connected 127.0.0.1:54226 at 0xb5773884> (<class 'AttributeError'>:TestSMTPChannel inst)
Traceback (most recent call last):
  File "/home/rdmurray/python/p33/Lib/logging/handlers.py", line 935, in emit
    smtp.sendmail(self.fromaddr, self.toaddrs, msg)
  File "/home/rdmurray/python/p33/Lib/smtplib.py", line 741, in sendmail
    self.ehlo_or_helo_if_needed()
  File "/home/rdmurray/python/p33/Lib/smtplib.py", line 550, in ehlo_or_helo_if_needed
    if not (200 <= self.ehlo()[0] <= 299):
  File "/home/rdmurray/python/p33/Lib/smtplib.py", line 417, in ehlo
    (code, msg) = self.getreply()
  File "/home/rdmurray/python/p33/Lib/smtplib.py", line 372, in getreply
    raise SMTPServerDisconnected("Connection unexpectedly closed")
smtplib.SMTPServerDisconnected: Connection unexpectedly closed
Logged from file , line 0

I think the event.wait() in the test should have a timeout; setting it to, say, 5 lets the tests complete (with a failure) in this situation.

Now the real issue:

Looking at the smtp handler code, I notice that unlike the socket handler it doesn't provide any way to set the timeout.  This means it could potentially hang forever trying to log an event, which while not related to the above issue is something that I think should be fixed.

I've marked this as behavior, since the SMTP connection should probably get a reasonable default timeout even in bug fix releases, but in 3.3 you'll probably want to make it settable and perhaps shorten the default relative to what you use for the maint releases.
msg155877 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2012-03-15 12:02
New changeset 4b3f81720809 by Vinay Sajip in branch 'default':
Fixes #14314: Improved SMTP timeout handling.
http://hg.python.org/cpython/rev/4b3f81720809
msg155878 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2012-03-15 12:05
I've added changes to the test code and a timeout to SMTPHandler (docs still to be updated), and I'll let it run on the buildbots for a bit before looking at timeouts for 3.2/2.7. Marking as pending to remind me.
msg156664 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2012-03-23 14:38
New changeset 113b8e3cbba4 by Vinay Sajip in branch '2.7':
Closes #14314: backported fix.
http://hg.python.org/cpython/rev/113b8e3cbba4

New changeset 54055646fd1f by Vinay Sajip in branch '3.2':
Closes #14314: backported fix.
http://hg.python.org/cpython/rev/54055646fd1f
History
Date User Action Args
2012-03-23 14:38:31python-devsetstatus: pending -> closed

messages: + msg156664
stage: needs patch -> resolved
2012-03-15 12:05:22vinay.sajipsetstatus: open -> pending
assignee: vinay.sajip
resolution: fixed
messages: + msg155878
2012-03-15 12:02:16python-devsetnosy: + python-dev
messages: + msg155877
2012-03-15 04:59:35r.david.murraycreate