classification
Title: timestamping in smtplib.py to help troubleshoot server timeouts/delays
Type: enhancement Stage: resolved
Components: email, Library (Lib) Versions: Python 3.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: barry, berker.peksag, gac, maciej.szulik, python-dev, r.david.murray
Priority: normal Keywords: patch

Created on 2013-01-10 12:41 by gac, last changed 2015-04-16 22:55 by python-dev. This issue is now closed.

Files
File name Uploaded Description Edit
smtplib.py.patch gac, 2013-01-10 12:41 patch to smtplib.py (3.4) to add debuglevel 2 review
smtplib.py.27.patch gac, 2013-01-11 08:46 patch to smtplib.py (2.7) to add debuglevel 2 review
smtplib.34.patch gac, 2013-01-14 10:56 second version of smtplib.py (3.4) patch review
issue16914.patch maciej.szulik, 2015-04-13 16:05 review
issue16914.patch maciej.szulik, 2015-04-13 22:54
issue16914.patch maciej.szulik, 2015-04-16 16:44 review
issue16914.patch maciej.szulik, 2015-04-16 19:48 review
Messages (17)
msg179538 - (view) Author: (gac) Date: 2013-01-10 12:41
I had cause to use smtplib to help me pinpoint why some outgoing mail was failing, but found that while it offered verbose logging (via debuglevel 1) this was without timestamps, making it difficult to make my case to the server operator that it was a server-side delay causing the issue. I've changed smtplib.py to add a second debugging level which includes timestamps down to microsecond granularity so that the debug log produced can pinpoint when a server isn't responding promptly.

debuglevel 1 is unchanged, so anyone depending on the output from this being in a particular format won't be affected (either by setting debuglevel to "1" or "true"), but if debuglevel 2 is used explicitly then the standard output is preceded by a timestamp.
msg179652 - (view) Author: (gac) Date: 2013-01-11 08:46
Patch to add the same functionality to Python 2.7, if anyone's interested in that also.
msg179931 - (view) Author: (gac) Date: 2013-01-14 10:56
Here's a second path I've done for the current/default branch, using a separate print function for output, as recommended by Berker Peksag. I tried to add it as a separate patch set using the code review tool but every time I did, I just got a screen full of debug output from Django so I'm going to attach it here instead.

The for loop on args inside _print_debug probably isn't ideal, but I've done this to try and make sure that debuglevel 1 output is identical to what it was before my patches. Because args is passed into _print_debug as a tuple, I found that when doing "print(message, args, file=stderr)" it introduced the extra parentheses and quotes inherent with a tuple into the output. By concatenating string representations of this tuple onto the existing string it means the original output format is duplicated exactly. There may be a speed penalty for this, but realistically it seems that a minor speed penalty would be expected when using debugging options and the output consistency trumps raw speed for debugging.

Once I've found a way of achieving the same in 2.7 (i.e. maintaining the original output format when being passed a tuple, the approach I've used for Python 3 doesn't seem to have the desired affect in 2.7) then I'll hopefully submit a patch for that as well.
msg179935 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2013-01-14 12:15
Thanks for the suggestion and patch.  I haven't reviewed it thoroughly yet, but if you change _print_debug to be:

   def _print_debug(*args):

then

   print(datetime.datetime.now(), *args, file=stderr)

should do what you want for python3 (I don't think the [] are needed, personally).  This patch won't be applied to 2.7, which I presume you know, so making that work would be for informational purposes only.
msg179936 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2013-01-14 12:16
Er, that should have been (self, *args), but actually I'd recommend making it a module function, not a method, in which case my signature would be correct :)
msg180133 - (view) Author: (gac) Date: 2013-01-17 14:10
Thanks, I'll look into your suggestions and try to submit a further improved patch :)
msg240639 - (view) Author: Maciej Szulik (maciej.szulik) * Date: 2015-04-13 16:05
Moving this enhancement to python 3.5. I'm adding updated patch plus tests for debug messages, updated what's new docs
msg240697 - (view) Author: Berker Peksag (berker.peksag) * (Python committer) Date: 2015-04-13 18:21
Thanks Maciej. I left a couple of comments on Rietveld: http://bugs.python.org/review/16914/
msg240797 - (view) Author: Maciej Szulik (maciej.szulik) * Date: 2015-04-13 22:54
Uploading updated version of the patch.
msg241235 - (view) Author: Maciej Szulik (maciej.szulik) * Date: 2015-04-16 16:44
After talking to David I'm submitting the patch once again with one slight change in ACKS file (I've put the names in the sorted order).
msg241264 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-04-16 19:17
Review comments added.
msg241269 - (view) Author: Maciej Szulik (maciej.szulik) * Date: 2015-04-16 19:48
Review comments addressed in latest patch.
msg241275 - (view) Author: Roundup Robot (python-dev) Date: 2015-04-16 21:15
New changeset 65037930edb0 by R David Murray in branch 'default':
#16914: add timestamps to smtplib debugging output via new debuglevel 2.
https://hg.python.org/cpython/rev/65037930edb0
msg241276 - (view) Author: Roundup Robot (python-dev) Date: 2015-04-16 21:16
New changeset de19c0ffe8d5 by R David Murray in branch 'default':
News item for #16914.
https://hg.python.org/cpython/rev/de19c0ffe8d5
msg241277 - (view) Author: Roundup Robot (python-dev) Date: 2015-04-16 21:25
New changeset 724473a18ada by R David Murray in branch 'default':
#16914: reflow paragraph and add missing versionchanged.
https://hg.python.org/cpython/rev/724473a18ada
msg241278 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-04-16 21:26
Thanks Gavin and Maciej.  I can tell it is the end of the sprints...my brain is fuzzy and I forgot both the news item and missed the missing versionchanged when I reviewed....
msg241288 - (view) Author: Roundup Robot (python-dev) Date: 2015-04-16 22:55
New changeset e532937914fc by R David Murray in branch 'default':
#16914: fix test errors under -W error::BytesWarning.
https://hg.python.org/cpython/rev/e532937914fc
History
Date User Action Args
2015-04-16 22:55:13python-devsetmessages: + msg241288
2015-04-16 21:26:16r.david.murraysetstatus: open -> closed
resolution: fixed
messages: + msg241278

stage: patch review -> resolved
2015-04-16 21:25:09python-devsetmessages: + msg241277
2015-04-16 21:16:24python-devsetmessages: + msg241276
2015-04-16 21:15:17python-devsetnosy: + python-dev
messages: + msg241275
2015-04-16 19:48:42maciej.szuliksetfiles: + issue16914.patch

messages: + msg241269
2015-04-16 19:17:57r.david.murraysetmessages: + msg241264
2015-04-16 16:44:30maciej.szuliksetfiles: + issue16914.patch

messages: + msg241235
2015-04-13 22:54:06maciej.szuliksetfiles: + issue16914.patch

messages: + msg240797
2015-04-13 18:21:29berker.peksagsetnosy: + berker.peksag
messages: + msg240697
2015-04-13 16:05:22maciej.szuliksetfiles: + issue16914.patch
versions: + Python 3.5, - Python 3.4
nosy: + maciej.szulik

messages: + msg240639
2013-01-17 14:10:08gacsetmessages: + msg180133
2013-01-14 12:16:49r.david.murraysetmessages: + msg179936
2013-01-14 12:15:30r.david.murraysetmessages: + msg179935
versions: - Python 2.7
2013-01-14 10:57:01gacsetfiles: + smtplib.34.patch

messages: + msg179931
2013-01-11 08:46:44gacsetfiles: + smtplib.py.27.patch

messages: + msg179652
versions: + Python 2.7
2013-01-10 16:49:34r.david.murraysetnosy: + barry, r.david.murray

components: + email
stage: patch review
2013-01-10 12:41:48gaccreate