#16914: add timestamps to smtplib debugging output via new debuglevel 2.

Patch by Gavin Chappell and Maciej Szulik.

5 files changed, 54 insertions, 16 deletions

diff --git a/Doc/library/smtplib.rst b/Doc/library/smtplib.rst
index 74de77b..2805a93 100644
--- a/Doc/library/smtplib.rst
+++ b/Doc/library/smtplib.rst
@@ -189,8 +189,9 @@ An :class:`SMTP` instance has the following methods:
 
 .. method:: SMTP.set_debuglevel(level)
 
-   Set the debug output level.  A true value for *level* results in debug messages
-   for connection and for all messages sent to and received from the server.
+   Set the debug output level.  A value of 1 or ``True`` for *level* results in debug
+   messages for connection and for all messages sent to and received from the server.
+   A value of 2 for *level* results in these messages being timestamped.
 
 
 .. method:: SMTP.docmd(cmd, args='')
diff --git a/Doc/whatsnew/3.5.rst b/Doc/whatsnew/3.5.rst
index 65119ed..0492ef9 100644
--- a/Doc/whatsnew/3.5.rst
+++ b/Doc/whatsnew/3.5.rst
@@ -468,6 +468,10 @@ smtplib
   implement custom authentication mechanisms.
   (Contributed by Milan Oberkirch in :issue:`15014`.)
 
+* Additional debuglevel (2) shows timestamps for debug messages in
+  :class:`smtplib.SMTP`.  (Contributed by Gavin Chappell and Maciej Szulik in
+  :issue:`16914`.)
+
 sndhdr
 ------
 
@@ -819,6 +823,11 @@ Changes in the Python API
 * The `pygettext.py` Tool now uses the standard +NNNN format for timezones in
   the POT-Creation-Date header.
 
+* The :mod:`smtplib` module now uses :data:`sys.stderr` instead of previous
+  module level :data:`stderr` variable for debug output.  If your (test)
+  program depends on patching the module level variable to capture the debug
+  output, you will need to update it to capture sys.stderr instead.
+
 
 Changes in the C API
 --------------------
diff --git a/Lib/smtplib.py b/Lib/smtplib.py
index 5c8dd72..c559a4c 100755
--- a/Lib/smtplib.py
+++ b/Lib/smtplib.py
@@ -50,8 +50,9 @@ import email.generator
 import base64
 import hmac
 import copy
+import datetime
+import sys
 from email.base64mime import body_encode as encode_base64
-from sys import stderr
 
 __all__ = ["SMTPException", "SMTPServerDisconnected", "SMTPResponseException",
            "SMTPSenderRefused", "SMTPRecipientsRefused", "SMTPDataError",
@@ -282,12 +283,17 @@ class SMTP:
         """
         self.debuglevel = debuglevel
 
+    def _print_debug(self, *args):
+        if self.debuglevel > 1:
+            print(datetime.datetime.now().time(), *args, file=sys.stderr)
+        else:
+            print(*args, file=sys.stderr)
+
     def _get_socket(self, host, port, timeout):
         # This makes it simpler for SMTP_SSL to use the SMTP connect code
         # and just alter the socket connection bit.
         if self.debuglevel > 0:
-            print('connect: to', (host, port), self.source_address,
-                                 file=stderr)
+            self._print_debug('connect: to', (host, port), self.source_address)
         return socket.create_connection((host, port), timeout,
                                         self.source_address)
 
@@ -317,18 +323,18 @@ class SMTP:
         if not port:
             port = self.default_port
         if self.debuglevel > 0:
-            print('connect:', (host, port), file=stderr)
+            self._print_debug('connect:', (host, port))
         self.sock = self._get_socket(host, port, self.timeout)
         self.file = None
         (code, msg) = self.getreply()
         if self.debuglevel > 0:
-            print("connect:", msg, file=stderr)
+            self._print_debug('connect:', msg)
         return (code, msg)
 
     def send(self, s):
         """Send `s' to the server."""
         if self.debuglevel > 0:
-            print('send:', repr(s), file=stderr)
+            self._print_debug('send:', repr(s))
         if hasattr(self, 'sock') and self.sock:
             if isinstance(s, str):
                 s = s.encode("ascii")
@@ -375,7 +381,7 @@ class SMTP:
                 self.close()
                 raise SMTPServerDisconnected("Connection unexpectedly closed")
             if self.debuglevel > 0:
-                print('reply:', repr(line), file=stderr)
+                self._print_debug('reply:', repr(line))
             if len(line) > _MAXLINE:
                 self.close()
                 raise SMTPResponseException(500, "Line too long.")
@@ -394,8 +400,7 @@ class SMTP:
 
         errmsg = b"\n".join(resp)
         if self.debuglevel > 0:
-            print('reply: retcode (%s); Msg: %s' % (errcode, errmsg),
-                                                    file=stderr)
+            self._print_debug('reply: retcode (%s); Msg: %s' % (errcode, errmsg))
         return errcode, errmsg
 
     def docmd(self, cmd, args=""):
@@ -524,7 +529,7 @@ class SMTP:
         self.putcmd("data")
         (code, repl) = self.getreply()
         if self.debuglevel > 0:
-            print("data:", (code, repl), file=stderr)
+            self._print_debug('data:', (code, repl))
         if code != 354:
             raise SMTPDataError(code, repl)
         else:
@@ -537,7 +542,7 @@ class SMTP:
             self.send(q)
             (code, msg) = self.getreply()
             if self.debuglevel > 0:
-                print("data:", (code, msg), file=stderr)
+                self._print_debug('data:', (code, msg))
             return (code, msg)
 
     def verify(self, address):
@@ -940,7 +945,7 @@ if _have_ssl:
 
         def _get_socket(self, host, port, timeout):
             if self.debuglevel > 0:
-                print('connect:', (host, port), file=stderr)
+                self._print_debug('connect:', (host, port))
             new_socket = socket.create_connection((host, port), timeout,
                     self.source_address)
             new_socket = self.context.wrap_socket(new_socket,
@@ -988,14 +993,14 @@ class LMTP(SMTP):
             self.sock.connect(host)
         except OSError:
             if self.debuglevel > 0:
-                print('connect fail:', host, file=stderr)
+                self._print_debug('connect fail:', host)
             if self.sock:
                 self.sock.close()
             self.sock = None
             raise
         (code, msg) = self.getreply()
         if self.debuglevel > 0:
-            print('connect:', msg, file=stderr)
+            self._print_debug('connect:', msg)
         return (code, msg)
 
 
diff --git a/Lib/test/test_smtplib.py b/Lib/test/test_smtplib.py
index 5f12d28..9011042 100644
--- a/Lib/test/test_smtplib.py
+++ b/Lib/test/test_smtplib.py
@@ -124,6 +124,27 @@ class GeneralTests(unittest.TestCase):
         self.assertEqual(smtp.sock.gettimeout(), 30)
         smtp.close()
 
+    def test_debuglevel(self):
+        mock_socket.reply_with(b"220 Hello world")
+        smtp = smtplib.SMTP()
+        smtp.set_debuglevel(1)
+        with support.captured_stderr() as stderr:
+            smtp.connect(HOST, self.port)
+        smtp.close()
+        expected = re.compile(r"^connect:", re.MULTILINE)
+        self.assertRegex(stderr.getvalue(), expected)
+
+    def test_debuglevel_2(self):
+        mock_socket.reply_with(b"220 Hello world")
+        smtp = smtplib.SMTP()
+        smtp.set_debuglevel(2)
+        with support.captured_stderr() as stderr:
+            smtp.connect(HOST, self.port)
+        smtp.close()
+        expected = re.compile(r"^\d{2}:\d{2}:\d{2}\.\d{6} connect: ",
+                              re.MULTILINE)
+        self.assertRegex(stderr.getvalue(), expected)
+
 
 # Test server thread using the specified SMTP server class
 def debugging_server(serv, serv_evt, client_evt):
diff --git a/Misc/ACKS b/Misc/ACKS
index 1641808..0a04a07 100644
--- a/Misc/ACKS
+++ b/Misc/ACKS
@@ -235,6 +235,7 @@ Pascal Chambon
 John Chandler
 Hye-Shik Chang
 Jeffrey Chang
+Gavin Chappell
 Godefroid Chapelle
 Brad Chapman
 Greg Chapman
@@ -1368,6 +1369,7 @@ Thenault Sylvain
 Péter Szabó
 John Szakmeister
 Amir Szekely
+Maciej Szulik
 Arfrever Frehtes Taifersar Arahesis
 Hideaki Takahashi
 Indra Talip