timestamping in smtplib.py to help troubleshoot server timeouts/delays

[gac]

BPO	16914
Nosy	@warsaw, @bitdancer, @berkerpeksag, @soltysh
Files	smtplib.py.patch: patch to smtplib.py (3.4) to add debuglevel 2 smtplib.py.27.patch: patch to smtplib.py (2.7) to add debuglevel 2 smtplib.34.patch: second version of smtplib.py (3.4) patch issue16914.patch issue16914.patch issue16914.patch issue16914.patch

^{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 = <Date 2015-04-16.21:26:16.077>
created_at = <Date 2013-01-10.12:41:48.066>
labels = ['type-feature', 'library', 'expert-email']
title = 'timestamping in smtplib.py to help troubleshoot server timeouts/delays'
updated_at = <Date 2015-04-16.22:55:13.584>
user = 'https://bugs.python.org/gac'

bugs.python.org fields:

activity = <Date 2015-04-16.22:55:13.584>
actor = 'python-dev'
assignee = 'none'
closed = True
closed_date = <Date 2015-04-16.21:26:16.077>
closer = 'r.david.murray'
components = ['Library (Lib)', 'email']
creation = <Date 2013-01-10.12:41:48.066>
creator = 'gac'
dependencies = []
files = ['28667', '28686', '28721', '38924', '38974', '39073', '39077']
hgrepos = []
issue_num = 16914
keywords = ['patch']
message_count = 17.0
messages = ['179538', '179652', '179931', '179935', '179936', '180133', '240639', '240697', '240797', '241235', '241264', '241269', '241275', '241276', '241277', '241278', '241288']
nosy_count = 6.0
nosy_names = ['barry', 'r.david.murray', 'python-dev', 'berker.peksag', 'maciej.szulik', 'gac']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'enhancement'
url = 'https://bugs.python.org/issue16914'
versions = ['Python 3.5']

[gac]

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.

[gac]

Patch to add the same functionality to Python 2.7, if anyone's interested in that also.

[gac]

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.

[bitdancer]

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.

[bitdancer]

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 :)

[gac]

Thanks, I'll look into your suggestions and try to submit a further improved patch :)

[soltysh]

Moving this enhancement to python 3.5. I'm adding updated patch plus tests for debug messages, updated what's new docs

[berkerpeksag]

Thanks Maciej. I left a couple of comments on Rietveld: http://bugs.python.org/review/16914/

[soltysh]

Uploading updated version of the patch.

[soltysh]

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

[bitdancer]

Review comments added.

[soltysh]

Review comments addressed in latest patch.