bpo-34271: Add ssl debugging helpers (GH-10031)

The ssl module now can dump key material to a keylog file and trace TLS
protocol messages with a tracing callback. The default and stdlib
contexts also support SSLKEYLOGFILE env var.

The msg_callback and related enums are private members. The feature
is designed for internal debugging and not for end users.

Signed-off-by: Christian Heimes <christian@python.org>

2 files changed, 306 insertions, 11 deletions

diff --git a/Modules/_ssl.c b/Modules/_ssl.c
index 4fb7dca..f40127d 100644
--- a/Modules/_ssl.c
+++ b/Modules/_ssl.c
@@ -185,6 +185,10 @@ static void _PySSLFixErrno(void) {
 # define HAVE_NPN 0
 #endif
 
+#if (OPENSSL_VERSION_NUMBER >= 0x10101000L) && !defined(LIBRESSL_VERSION_NUMBER)
+#define HAVE_OPENSSL_KEYLOG 1
+#endif
+
 #ifndef INVALID_SOCKET /* MS defines this */
 #define INVALID_SOCKET (-1)
 #endif
@@ -424,6 +428,11 @@ typedef struct {
 #ifdef TLS1_3_VERSION
     int post_handshake_auth;
 #endif
+    PyObject *msg_cb;
+#ifdef HAVE_OPENSSL_KEYLOG
+    PyObject *keylog_filename;
+    BIO *keylog_bio;
+#endif
 } PySSLContext;
 
 typedef struct {
@@ -444,6 +453,13 @@ typedef struct {
     PyObject *owner; /* Python level "owner" passed to servername callback */
     PyObject *server_hostname;
     _PySSLError err; /* last seen error from various sources */
+    /* Some SSL callbacks don't have error reporting. Callback wrappers
+     * store exception information on the socket. The handshake, read, write,
+     * and shutdown methods check for chained exceptions.
+     */
+    PyObject *exc_type;
+    PyObject *exc_value;
+    PyObject *exc_tb;
 } PySSLSocket;
 
 typedef struct {
@@ -517,6 +533,8 @@ typedef enum {
 #define GET_SOCKET_TIMEOUT(sock) \
     ((sock != NULL) ? (sock)->sock_timeout : 0)
 
+#include "_ssl/debughelpers.c"
+
 /*
  * SSL errors.
  */
@@ -703,6 +721,18 @@ fail:
     Py_XDECREF(verify_obj);
 }
 
+static int
+PySSL_ChainExceptions(PySSLSocket *sslsock) {
+    if (sslsock->exc_type == NULL)
+        return 0;
+
+    _PyErr_ChainExceptions(sslsock->exc_type, sslsock->exc_value, sslsock->exc_tb);
+    sslsock->exc_type = NULL;
+    sslsock->exc_value = NULL;
+    sslsock->exc_tb = NULL;
+    return -1;
+}
+
 static PyObject *
 PySSL_SetError(PySSLSocket *sslsock, int ret, const char *filename, int lineno)
 {
@@ -796,6 +826,7 @@ PySSL_SetError(PySSLSocket *sslsock, int ret, const char *filename, int lineno)
     }
     fill_and_set_sslerror(sslsock, type, p, errstr, lineno, e);
     ERR_clear_error();
+    PySSL_ChainExceptions(sslsock);
     return NULL;
 }
 
@@ -903,6 +934,9 @@ newPySSLSocket(PySSLContext *sslctx, PySocketSockObject *sock,
     self->owner = NULL;
     self->server_hostname = NULL;
     self->err = err;
+    self->exc_type = NULL;
+    self->exc_value = NULL;
+    self->exc_tb = NULL;
 
     /* Make sure the SSL error state is initialized */
     ERR_clear_error();
@@ -1052,11 +1086,12 @@ _ssl__SSLSocket_do_handshake_impl(PySSLSocket *self)
     Py_XDECREF(sock);
     if (ret < 1)
         return PySSL_SetError(self, ret, __FILE__, __LINE__);
-
+    if (PySSL_ChainExceptions(self) < 0)
+        return NULL;
     Py_RETURN_NONE;
-
 error:
     Py_XDECREF(sock);
+    PySSL_ChainExceptions(self);
     return NULL;
 }
 
@@ -2151,8 +2186,26 @@ PyDoc_STRVAR(PySSL_get_owner_doc,
 "The Python-level owner of this object.\
 Passed as \"self\" in servername callback.");
 
+static int
+PySSL_traverse(PySSLSocket *self, visitproc visit, void *arg)
+{
+    Py_VISIT(self->exc_type);
+    Py_VISIT(self->exc_value);
+    Py_VISIT(self->exc_tb);
+    return 0;
+}
+
+static int
+PySSL_clear(PySSLSocket *self)
+{
+    Py_CLEAR(self->exc_type);
+    Py_CLEAR(self->exc_value);
+    Py_CLEAR(self->exc_tb);
+    return 0;
+}
 
-static void PySSL_dealloc(PySSLSocket *self)
+static void
+PySSL_dealloc(PySSLSocket *self)
 {
     if (self->ssl)
         SSL_free(self->ssl);
@@ -2333,13 +2386,14 @@ _ssl__SSLSocket_write_impl(PySSLSocket *self, Py_buffer *b)
              err.ssl == SSL_ERROR_WANT_WRITE);
 
     Py_XDECREF(sock);
-    if (len > 0)
-        return PyLong_FromLong(len);
-    else
+    if (len <= 0)
         return PySSL_SetError(self, len, __FILE__, __LINE__);
-
+    if (PySSL_ChainExceptions(self) < 0)
+        return NULL;
+    return PyLong_FromLong(len);
 error:
     Py_XDECREF(sock);
+    PySSL_ChainExceptions(self);
     return NULL;
 }
 
@@ -2486,6 +2540,8 @@ _ssl__SSLSocket_read_impl(PySSLSocket *self, int len, int group_right_1,
         PySSL_SetError(self, count, __FILE__, __LINE__);
         goto error;
     }
+    if (self->exc_type != NULL)
+        goto error;
 
 done:
     Py_XDECREF(sock);
@@ -2498,6 +2554,7 @@ done:
     }
 
 error:
+    PySSL_ChainExceptions(self);
     Py_XDECREF(sock);
     if (!group_right_1)
         Py_XDECREF(dest);
@@ -2601,11 +2658,13 @@ _ssl__SSLSocket_shutdown_impl(PySSLSocket *self)
             /* Retain the SSL error code */
             break;
     }
-
     if (ret < 0) {
         Py_XDECREF(sock);
-        return PySSL_SetError(self, ret, __FILE__, __LINE__);
+        PySSL_SetError(self, ret, __FILE__, __LINE__);
+        return NULL;
     }
+    if (self->exc_type != NULL)
+        goto error;
     if (sock)
         /* It's already INCREF'ed */
         return (PyObject *) sock;
@@ -2614,6 +2673,7 @@ _ssl__SSLSocket_shutdown_impl(PySSLSocket *self)
 
 error:
     Py_XDECREF(sock);
+    PySSL_ChainExceptions(self);
     return NULL;
 }
 
@@ -2889,8 +2949,8 @@ static PyTypeObject PySSLSocket_Type = {
     0,                                  /*tp_as_buffer*/
     Py_TPFLAGS_DEFAULT,                 /*tp_flags*/
     0,                                  /*tp_doc*/
-    0,                                  /*tp_traverse*/
-    0,                                  /*tp_clear*/
+    (traverseproc) PySSL_traverse,      /*tp_traverse*/
+    (inquiry) PySSL_clear,              /*tp_clear*/
     0,                                  /*tp_richcompare*/
     0,                                  /*tp_weaklistoffset*/
     0,                                  /*tp_iter*/
@@ -3002,6 +3062,11 @@ _ssl__SSLContext_impl(PyTypeObject *type, int proto_version)
     self->ctx = ctx;
     self->hostflags = X509_CHECK_FLAG_NO_PARTIAL_WILDCARDS;
     self->protocol = proto_version;
+    self->msg_cb = NULL;
+#ifdef HAVE_OPENSSL_KEYLOG
+    self->keylog_filename = NULL;
+    self->keylog_bio = NULL;
+#endif
 #if HAVE_NPN
     self->npn_protocols = NULL;
 #endif
@@ -3127,6 +3192,7 @@ context_traverse(PySSLContext *self, visitproc visit, void *arg)
 #ifndef OPENSSL_NO_TLSEXT
     Py_VISIT(self->set_sni_cb);
 #endif
+    Py_VISIT(self->msg_cb);
     return 0;
 }
 
@@ -3136,6 +3202,16 @@ context_clear(PySSLContext *self)
 #ifndef OPENSSL_NO_TLSEXT
     Py_CLEAR(self->set_sni_cb);
 #endif
+    Py_CLEAR(self->msg_cb);
+#ifdef HAVE_OPENSSL_KEYLOG
+    Py_CLEAR(self->keylog_filename);
+    if (self->keylog_bio != NULL) {
+        PySSL_BEGIN_ALLOW_THREADS
+        BIO_free_all(self->keylog_bio);
+        PySSL_END_ALLOW_THREADS
+        self->keylog_bio = NULL;
+    }
+#endif
     return 0;
 }
 
@@ -4570,6 +4646,12 @@ static PyGetSetDef context_getsetlist[] = {
     {"maximum_version", (getter) get_maximum_version,
                         (setter) set_maximum_version, NULL},
 #endif
+#ifdef HAVE_OPENSSL_KEYLOG
+    {"keylog_filename", (getter) _PySSLContext_get_keylog_filename,
+                        (setter) _PySSLContext_set_keylog_filename, NULL},
+#endif
+    {"_msg_callback", (getter) _PySSLContext_get_msg_callback,
+                      (setter) _PySSLContext_set_msg_callback, NULL},
     {"sni_callback", (getter) get_sni_callback,
                      (setter) set_sni_callback, PySSLContext_sni_callback_doc},
     {"options", (getter) get_options,
diff --git a/Modules/_ssl/debughelpers.c b/Modules/_ssl/debughelpers.c
new file mode 100644
index 0000000..53b9667
--- /dev/null
+++ b/Modules/_ssl/debughelpers.c
@@ -0,0 +1,213 @@
+/* Debug helpers */
+
+static void
+_PySSL_msg_callback(int write_p, int version, int content_type,
+                    const void *buf, size_t len, SSL *ssl, void *arg)
+{
+    const char *cbuf = (const char *)buf;
+    PyGILState_STATE threadstate;
+    PyObject *res = NULL;
+    PySSLSocket *ssl_obj = NULL;  /* ssl._SSLSocket, borrowed ref */
+    PyObject *ssl_socket = NULL;  /* ssl.SSLSocket or ssl.SSLObject */
+    int msg_type;
+
+    threadstate = PyGILState_Ensure();
+
+    ssl_obj = (PySSLSocket *)SSL_get_app_data(ssl);
+    assert(PySSLSocket_Check(ssl_obj));
+    if (ssl_obj->ctx->msg_cb == NULL) {
+        return;
+    }
+
+    if (ssl_obj->owner)
+        ssl_socket = PyWeakref_GetObject(ssl_obj->owner);
+    else if (ssl_obj->Socket)
+        ssl_socket = PyWeakref_GetObject(ssl_obj->Socket);
+    else
+        ssl_socket = (PyObject *)ssl_obj;
+    Py_INCREF(ssl_socket);
+
+    /* assume that OpenSSL verifies all payload and buf len is of sufficient
+       length */
+    switch(content_type) {
+      case SSL3_RT_CHANGE_CIPHER_SPEC:
+        msg_type = SSL3_MT_CHANGE_CIPHER_SPEC;
+        break;
+      case SSL3_RT_ALERT:
+        /* byte 0: level */
+        /* byte 1: alert type */
+        msg_type = (int)cbuf[1];
+        break;
+      case SSL3_RT_HANDSHAKE:
+        msg_type = (int)cbuf[0];
+        break;
+      case SSL3_RT_HEADER:
+        /* frame header encodes version in bytes 1..2 */
+        version = cbuf[1] << 8 | cbuf[2];
+        msg_type = (int)cbuf[0];
+        break;
+#ifdef SSL3_RT_INNER_CONTENT_TYPE
+      case SSL3_RT_INNER_CONTENT_TYPE:
+        msg_type = (int)cbuf[0];
+        break;
+#endif
+      default:
+        /* never SSL3_RT_APPLICATION_DATA */
+        msg_type = -1;
+        break;
+    }
+
+    res = PyObject_CallFunction(
+        ssl_obj->ctx->msg_cb, "Osiiiy#",
+        ssl_socket, write_p ? "write" : "read",
+        version, content_type, msg_type,
+        buf, len
+    );
+    if (res == NULL) {
+        PyErr_Fetch(&ssl_obj->exc_type, &ssl_obj->exc_value, &ssl_obj->exc_tb);
+    } else {
+        Py_DECREF(res);
+    }
+    Py_XDECREF(ssl_socket);
+
+    PyGILState_Release(threadstate);
+}
+
+
+static PyObject *
+_PySSLContext_get_msg_callback(PySSLContext *self, void *c) {
+    if (self->msg_cb != NULL) {
+        Py_INCREF(self->msg_cb);
+        return self->msg_cb;
+    } else {
+        Py_RETURN_NONE;
+    }
+}
+
+static int
+_PySSLContext_set_msg_callback(PySSLContext *self, PyObject *arg, void *c) {
+    Py_CLEAR(self->msg_cb);
+    if (arg == Py_None) {
+        SSL_CTX_set_msg_callback(self->ctx, NULL);
+    }
+    else {
+        if (!PyCallable_Check(arg)) {
+            SSL_CTX_set_msg_callback(self->ctx, NULL);
+            PyErr_SetString(PyExc_TypeError,
+                            "not a callable object");
+            return -1;
+        }
+        Py_INCREF(arg);
+        self->msg_cb = arg;
+        SSL_CTX_set_msg_callback(self->ctx, _PySSL_msg_callback);
+    }
+    return 0;
+}
+
+#ifdef HAVE_OPENSSL_KEYLOG
+
+static void
+_PySSL_keylog_callback(const SSL *ssl, const char *line)
+{
+    PyGILState_STATE threadstate;
+    PySSLSocket *ssl_obj = NULL;  /* ssl._SSLSocket, borrowed ref */
+    int res, e;
+    static PyThread_type_lock *lock = NULL;
+
+    threadstate = PyGILState_Ensure();
+
+    /* Allocate a static lock to synchronize writes to keylog file.
+     * The lock is neither released on exit nor on fork(). The lock is
+     * also shared between all SSLContexts although contexts may write to
+     * their own files. IMHO that's good enough for a non-performance
+     * critical debug helper.
+     */
+    if (lock == NULL) {
+        lock = PyThread_allocate_lock();
+        if (lock == NULL) {
+            PyErr_SetString(PyExc_MemoryError, "Unable to allocate lock");
+            PyErr_Fetch(&ssl_obj->exc_type, &ssl_obj->exc_value,
+                        &ssl_obj->exc_tb);
+            return;
+        }
+    }
+
+    ssl_obj = (PySSLSocket *)SSL_get_app_data(ssl);
+    assert(PySSLSocket_Check(ssl_obj));
+    if (ssl_obj->ctx->keylog_bio == NULL) {
+        return;
+    }
+
+    PySSL_BEGIN_ALLOW_THREADS
+    PyThread_acquire_lock(lock, 1);
+    res = BIO_printf(ssl_obj->ctx->keylog_bio, "%s\n", line);
+    e = errno;
+    (void)BIO_flush(ssl_obj->ctx->keylog_bio);
+    PyThread_release_lock(lock);
+    PySSL_END_ALLOW_THREADS
+
+    if (res == -1) {
+        errno = e;
+        PyErr_SetFromErrnoWithFilenameObject(PyExc_OSError,
+                                             ssl_obj->ctx->keylog_filename);
+        PyErr_Fetch(&ssl_obj->exc_type, &ssl_obj->exc_value, &ssl_obj->exc_tb);
+    }
+    PyGILState_Release(threadstate);
+}
+
+static PyObject *
+_PySSLContext_get_keylog_filename(PySSLContext *self, void *c) {
+    if (self->keylog_filename != NULL) {
+        Py_INCREF(self->keylog_filename);
+        return self->keylog_filename;
+    } else {
+        Py_RETURN_NONE;
+    }
+}
+
+static int
+_PySSLContext_set_keylog_filename(PySSLContext *self, PyObject *arg, void *c) {
+    FILE *fp;
+    /* Reset variables and callback first */
+    SSL_CTX_set_keylog_callback(self->ctx, NULL);
+    Py_CLEAR(self->keylog_filename);
+    if (self->keylog_bio != NULL) {
+        BIO *bio = self->keylog_bio;
+        self->keylog_bio = NULL;
+        PySSL_BEGIN_ALLOW_THREADS
+        BIO_free_all(bio);
+        PySSL_END_ALLOW_THREADS
+    }
+
+    if (arg == Py_None) {
+        /* None disables the callback */
+        return 0;
+    }
+
+    /* _Py_fopen_obj() also checks that arg is of proper type. */
+    fp = _Py_fopen_obj(arg, "a" PY_STDIOTEXTMODE);
+    if (fp == NULL)
+        return -1;
+
+    self->keylog_bio = BIO_new_fp(fp, BIO_CLOSE | BIO_FP_TEXT);
+    if (self->keylog_bio == NULL) {
+        PyErr_SetString(PySSLErrorObject,
+                        "Can't malloc memory for keylog file");
+        return -1;
+    }
+    Py_INCREF(arg);
+    self->keylog_filename = arg;
+
+    /* Write a header for seekable, empty files (this excludes pipes). */
+    PySSL_BEGIN_ALLOW_THREADS
+    if (BIO_tell(self->keylog_bio) == 0) {
+        BIO_puts(self->keylog_bio,
+                 "# TLS secrets log file, generated by OpenSSL / Python\n");
+        (void)BIO_flush(self->keylog_bio);
+    }
+    PySSL_END_ALLOW_THREADS
+    SSL_CTX_set_keylog_callback(self->ctx, _PySSL_keylog_callback);
+    return 0;
+}
+
+#endif
\ No newline at end of file