vtls: Extract and simplify key log file handling from OpenSSL

Create a set of routines for TLS key log file handling to enable reuse
with other TLS backends. Simplify the OpenSSL backend as follows:

 - Drop the ENABLE_SSLKEYLOGFILE macro as it is unconditionally enabled.
 - Do not perform dynamic memory allocation when preparing a log entry.
   Unless the TLS specifications change we can suffice with a reasonable
   fixed-size buffer.
 - Simplify state tracking when SSL_CTX_set_keylog_callback is
   unavailable. My original sslkeylog.c code included this tracking in
   order to handle multiple calls to SSL_connect and detect new keys
   after renegotiation (via SSL_read/SSL_write). For curl however we can
   be sure that a single master secret eventually becomes available
   after SSL_connect, so a simple flag is sufficient. An alternative to
   the flag is examining SSL_state(), but this seems more complex and is
   not pursued. Capturing keys after server renegotiation was already
   unsupported in curl and remains unsupported.

Tested with curl built against OpenSSL 0.9.8zh, 1.0.2u, and 1.1.1f
(`SSLKEYLOGFILE=keys.txt curl -vkso /dev/null https://localhost:4433`)
against an OpenSSL 1.1.1f server configured with:

    # Force non-TLSv1.3, use TLSv1.0 since 0.9.8 fails with 1.1 or 1.2
    openssl s_server -www -tls1
    # Likewise, but fail the server handshake.
    openssl s_server -www -tls1 -Verify 2
    # TLS 1.3 test. No need to test the failing server handshake.
    openssl s_server -www -tls1_3

Verify that all secrets (1 for TLS 1.0, 4 for TLS 1.3) are correctly
written using Wireshark. For the first and third case, expect four
matches per connection (decrypted Server Finished, Client Finished, HTTP
Request, HTTP Response). For the second case where the handshake fails,
expect a decrypted Server Finished only.

    tshark -i lo -pf tcp -otls.keylog_file:keys.txt -Tfields \
        -eframe.number -eframe.time -etcp.stream -e_ws.col.Info \
        -dtls.port==4433,http -ohttp.desegment_body:FALSE \
        -Y 'tls.handshake.verify_data or http'

A single connection can easily be identified via the `tcp.stream` field.

4 files changed, 246 insertions, 125 deletions

diff --git a/lib/Makefile.inc b/lib/Makefile.inc
index 08b0f73a3..723b826e9 100644
--- a/lib/Makefile.inc
+++ b/lib/Makefile.inc
@@ -27,14 +27,14 @@ LIB_VAUTH_CFILES = vauth/cleartext.c vauth/cram.c vauth/digest.c             \
 
 LIB_VAUTH_HFILES = vauth/digest.h vauth/ntlm.h vauth/vauth.h
 
-LIB_VTLS_CFILES = vtls/bearssl.c vtls/gskit.c vtls/gtls.c vtls/mbedtls.c \
-  vtls/mbedtls_threadlock.c vtls/mesalink.c vtls/nss.c vtls/openssl.c    \
-  vtls/schannel.c vtls/schannel_verify.c vtls/sectransp.c vtls/vtls.c    \
-  vtls/wolfssl.c
+LIB_VTLS_CFILES = vtls/bearssl.c vtls/gskit.c vtls/gtls.c vtls/keylog.c  \
+  vtls/mbedtls.c vtls/mbedtls_threadlock.c vtls/mesalink.c vtls/nss.c    \
+  vtls/openssl.c vtls/schannel.c vtls/schannel_verify.c vtls/sectransp.c \
+  vtls/vtls.c vtls/wolfssl.c
 
-LIB_VTLS_HFILES = vtls/bearssl.h vtls/gskit.h vtls/gtls.h vtls/mbedtls.h \
-  vtls/mbedtls_threadlock.h vtls/mesalink.h vtls/nssg.h vtls/openssl.h   \
-  vtls/schannel.h vtls/sectransp.h vtls/vtls.h vtls/wolfssl.h
+LIB_VTLS_HFILES = vtls/bearssl.h vtls/gskit.h vtls/gtls.h vtls/keylog.h      \
+  vtls/mbedtls.h vtls/mbedtls_threadlock.h vtls/mesalink.h vtls/nssg.h       \
+  vtls/openssl.h vtls/schannel.h vtls/sectransp.h vtls/vtls.h vtls/wolfssl.h
 
 LIB_VQUIC_CFILES = vquic/ngtcp2.c vquic/quiche.c vquic/vquic.c
 
diff --git a/lib/vtls/keylog.c b/lib/vtls/keylog.c
new file mode 100644
index 000000000..70d22ecf0
--- /dev/null
+++ b/lib/vtls/keylog.c
@@ -0,0 +1,156 @@
+/***************************************************************************
+ *                                  _   _ ____  _
+ *  Project                     ___| | | |  _ \| |
+ *                             / __| | | | |_) | |
+ *                            | (__| |_| |  _ <| |___
+ *                             \___|\___/|_| \_\_____|
+ *
+ * Copyright (C) 1998 - 2020, Daniel Stenberg, <daniel@haxx.se>, et al.
+ *
+ * This software is licensed as described in the file COPYING, which
+ * you should have received as part of this distribution. The terms
+ * are also available at https://curl.haxx.se/docs/copyright.html.
+ *
+ * You may opt to use, copy, modify, merge, publish, distribute and/or sell
+ * copies of the Software, and permit persons to whom the Software is
+ * furnished to do so, under the terms of the COPYING file.
+ *
+ * This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY
+ * KIND, either express or implied.
+ *
+ ***************************************************************************/
+#include "curl_setup.h"
+
+#include "keylog.h"
+
+/* The last #include files should be: */
+#include "curl_memory.h"
+#include "memdebug.h"
+
+#define KEYLOG_LABEL_MAXLEN (sizeof("CLIENT_HANDSHAKE_TRAFFIC_SECRET") - 1)
+
+#define CLIENT_RANDOM_SIZE  32
+
+/*
+ * The master secret in TLS 1.2 and before is always 48 bytes. In TLS 1.3, the
+ * secret size depends on the cipher suite's hash function which is 32 bytes
+ * for SHA-256 and 48 bytes for SHA-384.
+ */
+#define SECRET_MAXLEN       48
+
+
+/* The fp for the open SSLKEYLOGFILE, or NULL if not open */
+static FILE *keylog_file_fp;
+
+void
+Curl_tls_keylog_open(void)
+{
+  char *keylog_file_name;
+
+  if(!keylog_file_fp) {
+    keylog_file_name = curl_getenv("SSLKEYLOGFILE");
+    if(keylog_file_name) {
+      keylog_file_fp = fopen(keylog_file_name, FOPEN_APPENDTEXT);
+      if(keylog_file_fp) {
+#ifdef WIN32
+        if(setvbuf(keylog_file_fp, NULL, _IONBF, 0))
+#else
+        if(setvbuf(keylog_file_fp, NULL, _IOLBF, 4096))
+#endif
+        {
+          fclose(keylog_file_fp);
+          keylog_file_fp = NULL;
+        }
+      }
+      Curl_safefree(keylog_file_name);
+    }
+  }
+}
+
+void
+Curl_tls_keylog_close(void)
+{
+  if(keylog_file_fp) {
+    fclose(keylog_file_fp);
+    keylog_file_fp = NULL;
+  }
+}
+
+bool
+Curl_tls_keylog_enabled(void)
+{
+  return keylog_file_fp != NULL;
+}
+
+bool
+Curl_tls_keylog_write_line(const char *line)
+{
+  /* The current maximum valid keylog line length LF and NUL is 195. */
+  size_t linelen;
+  char buf[256];
+
+  if(!keylog_file_fp || !line) {
+    return false;
+  }
+
+  linelen = strlen(line);
+  if(linelen == 0 || linelen > sizeof(buf) - 2) {
+    /* Empty line or too big to fit in a LF and NUL. */
+    return false;
+  }
+
+  memcpy(buf, line, linelen);
+  if(line[linelen - 1] != '\n') {
+    buf[linelen++] = '\n';
+  }
+  buf[linelen] = '\0';
+
+  /* Using fputs here instead of fprintf since libcurl's fprintf replacement
+     may not be thread-safe. */
+  fputs(buf, keylog_file_fp);
+  return true;
+}
+
+bool
+Curl_tls_keylog_write(const char *label,
+                      const unsigned char client_random[CLIENT_RANDOM_SIZE],
+                      const unsigned char *secret, size_t secretlen)
+{
+  const char *hex = "0123456789ABCDEF";
+  size_t pos, i;
+  char line[KEYLOG_LABEL_MAXLEN + 1 + 2 * CLIENT_RANDOM_SIZE + 1 +
+            2 * SECRET_MAXLEN + 1 + 1];
+
+  if(!keylog_file_fp) {
+    return false;
+  }
+
+  pos = strlen(label);
+  if(pos > KEYLOG_LABEL_MAXLEN || !secretlen || secretlen > SECRET_MAXLEN) {
+    /* Should never happen - sanity check anyway. */
+    return false;
+  }
+
+  memcpy(line, label, pos);
+  line[pos++] = ' ';
+
+  /* Client Random */
+  for(i = 0; i < CLIENT_RANDOM_SIZE; i++) {
+    line[pos++] = hex[client_random[i] >> 4];
+    line[pos++] = hex[client_random[i] & 0xF];
+  }
+  line[pos++] = ' ';
+
+  /* Secret */
+  for(i = 0; i < secretlen; i++) {
+    line[pos++] = hex[secret[i] >> 4];
+    line[pos++] = hex[secret[i] & 0xF];
+  }
+  line[pos++] = '\n';
+  line[pos] = '\0';
+
+  /* Using fputs here instead of fprintf since libcurl's fprintf replacement
+     may not be thread-safe. */
+  fputs(line, keylog_file_fp);
+  return true;
+}
diff --git a/lib/vtls/keylog.h b/lib/vtls/keylog.h
new file mode 100644
index 000000000..c6b99db93
--- /dev/null
+++ b/lib/vtls/keylog.h
@@ -0,0 +1,56 @@
+#ifndef HEADER_CURL_KEYLOG_H
+#define HEADER_CURL_KEYLOG_H
+/***************************************************************************
+ *                                  _   _ ____  _
+ *  Project                     ___| | | |  _ \| |
+ *                             / __| | | | |_) | |
+ *                            | (__| |_| |  _ <| |___
+ *                             \___|\___/|_| \_\_____|
+ *
+ * Copyright (C) 1998 - 2020, Daniel Stenberg, <daniel@haxx.se>, et al.
+ *
+ * This software is licensed as described in the file COPYING, which
+ * you should have received as part of this distribution. The terms
+ * are also available at https://curl.haxx.se/docs/copyright.html.
+ *
+ * You may opt to use, copy, modify, merge, publish, distribute and/or sell
+ * copies of the Software, and permit persons to whom the Software is
+ * furnished to do so, under the terms of the COPYING file.
+ *
+ * This software is distributed on an "AS IS" basis, WITHOUT WARRANTY OF ANY
+ * KIND, either express or implied.
+ *
+ ***************************************************************************/
+#include "curl_setup.h"
+
+/*
+ * Opens the TLS key log file if requested by the user. The SSLKEYLOGFILE
+ * environment variable specifies the output file.
+ */
+void Curl_tls_keylog_open(void);
+
+/*
+ * Closes the TLS key log file if not already.
+ */
+void Curl_tls_keylog_close(void);
+
+/*
+ * Returns true if the user successfully enabled the TLS key log file.
+ */
+bool Curl_tls_keylog_enabled(void);
+
+/*
+ * Appends a key log file entry.
+ * Returns true iff the key log file is open and a valid entry was provided.
+ */
+bool Curl_tls_keylog_write(const char *label,
+                           const unsigned char client_random[32],
+                           const unsigned char *secret, size_t secretlen);
+
+/*
+ * Appends a line to the key log file, ensure it is terminated by a LF.
+ * Returns true iff the key log file is open and a valid line was provided.
+ */
+bool Curl_tls_keylog_write_line(const char *line);
+
+#endif /* HEADER_CURL_KEYLOG_H */
diff --git a/lib/vtls/openssl.c b/lib/vtls/openssl.c
index e4d50fe08..56920deed 100644
--- a/lib/vtls/openssl.c
+++ b/lib/vtls/openssl.c
@@ -41,6 +41,7 @@
 #include "slist.h"
 #include "select.h"
 #include "vtls.h"
+#include "keylog.h"
 #include "strcase.h"
 #include "hostcheck.h"
 #include "multiif.h"
@@ -212,24 +213,14 @@
   "ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH"
 #endif
 
-#define ENABLE_SSLKEYLOGFILE
-
-#ifdef ENABLE_SSLKEYLOGFILE
-struct ssl_tap_state {
-  int master_key_length;
-  unsigned char master_key[SSL_MAX_MASTER_KEY_LENGTH];
-  unsigned char client_random[SSL3_RANDOM_SIZE];
-};
-#endif /* ENABLE_SSLKEYLOGFILE */
-
 struct ssl_backend_data {
   /* these ones requires specific SSL-types */
   SSL_CTX* ctx;
   SSL*     handle;
   X509*    server_cert;
-#ifdef ENABLE_SSLKEYLOGFILE
-  /* tap_state holds the last seen master key if we're logging them */
-  struct ssl_tap_state tap_state;
+#ifndef HAVE_KEYLOG_CALLBACK
+  /* Set to true once a valid keylog entry has been created to avoid dupes. */
+  bool     keylog_done;
 #endif
 };
 
@@ -241,57 +232,27 @@ struct ssl_backend_data {
  */
 #define RAND_LOAD_LENGTH 1024
 
-#ifdef ENABLE_SSLKEYLOGFILE
-/* The fp for the open SSLKEYLOGFILE, or NULL if not open */
-static FILE *keylog_file_fp;
-
 #ifdef HAVE_KEYLOG_CALLBACK
 static void ossl_keylog_callback(const SSL *ssl, const char *line)
 {
   (void)ssl;
 
-  /* Using fputs here instead of fprintf since libcurl's fprintf replacement
-     may not be thread-safe. */
-  if(keylog_file_fp && line && *line) {
-    char stackbuf[256];
-    char *buf;
-    size_t linelen = strlen(line);
-
-    if(linelen <= sizeof(stackbuf) - 2)
-      buf = stackbuf;
-    else {
-      buf = malloc(linelen + 2);
-      if(!buf)
-        return;
-    }
-    memcpy(buf, line, linelen);
-    buf[linelen] = '\n';
-    buf[linelen + 1] = '\0';
-
-    fputs(buf, keylog_file_fp);
-    if(buf != stackbuf)
-      free(buf);
-  }
+  Curl_tls_keylog_write_line(line);
 }
 #else
-#define KEYLOG_PREFIX      "CLIENT_RANDOM "
-#define KEYLOG_PREFIX_LEN  (sizeof(KEYLOG_PREFIX) - 1)
 /*
- * tap_ssl_key is called by libcurl to make the CLIENT_RANDOMs if the OpenSSL
- * being used doesn't have native support for doing that.
+ * ossl_log_tls12_secret is called by libcurl to make the CLIENT_RANDOMs if the
+ * OpenSSL being used doesn't have native support for doing that.
  */
-static void tap_ssl_key(const SSL *ssl, struct ssl_tap_state *state)
+static void
+ossl_log_tls12_secret(const SSL *ssl, bool *keylog_done)
 {
-  const char *hex = "0123456789ABCDEF";
-  int pos, i;
-  char line[KEYLOG_PREFIX_LEN + 2 * SSL3_RANDOM_SIZE + 1 +
-            2 * SSL_MAX_MASTER_KEY_LENGTH + 1 + 1];
   const SSL_SESSION *session = SSL_get_session(ssl);
   unsigned char client_random[SSL3_RANDOM_SIZE];
   unsigned char master_key[SSL_MAX_MASTER_KEY_LENGTH];
   int master_key_length = 0;
 
-  if(!session || !keylog_file_fp)
+  if(!session || *keylog_done)
     return;
 
 #if OPENSSL_VERSION_NUMBER >= 0x10100000L && \
@@ -310,44 +271,17 @@ static void tap_ssl_key(const SSL *ssl, struct ssl_tap_state *state)
   }
 #endif
 
+  /* The handshake has not progressed sufficiently yet, or this is a TLS 1.3
+   * session (when curl was built with older OpenSSL headers and running with
+   * newer OpenSSL runtime libraries). */
   if(master_key_length <= 0)
     return;
 
-  /* Skip writing keys if there is no key or it did not change. */
-  if(state->master_key_length == master_key_length &&
-     !memcmp(state->master_key, master_key, master_key_length) &&
-     !memcmp(state->client_random, client_random, SSL3_RANDOM_SIZE)) {
-    return;
-  }
-
-  state->master_key_length = master_key_length;
-  memcpy(state->master_key, master_key, master_key_length);
-  memcpy(state->client_random, client_random, SSL3_RANDOM_SIZE);
-
-  memcpy(line, KEYLOG_PREFIX, KEYLOG_PREFIX_LEN);
-  pos = KEYLOG_PREFIX_LEN;
-
-  /* Client Random for SSLv3/TLS */
-  for(i = 0; i < SSL3_RANDOM_SIZE; i++) {
-    line[pos++] = hex[client_random[i] >> 4];
-    line[pos++] = hex[client_random[i] & 0xF];
-  }
-  line[pos++] = ' ';
-
-  /* Master Secret (size is at most SSL_MAX_MASTER_KEY_LENGTH) */
-  for(i = 0; i < master_key_length; i++) {
-    line[pos++] = hex[master_key[i] >> 4];
-    line[pos++] = hex[master_key[i] & 0xF];
-  }
-  line[pos++] = '\n';
-  line[pos] = '\0';
-
-  /* Using fputs here instead of fprintf since libcurl's fprintf replacement
-     may not be thread-safe. */
-  fputs(line, keylog_file_fp);
+  *keylog_done = true;
+  Curl_tls_keylog_write("CLIENT_RANDOM", client_random,
+                        master_key, master_key_length);
 }
 #endif /* !HAVE_KEYLOG_CALLBACK */
-#endif /* ENABLE_SSLKEYLOGFILE */
 
 static const char *SSL_ERROR_to_str(int err)
 {
@@ -1163,10 +1097,6 @@ static int x509_name_oneline(X509_NAME *a, char *buf, size_t size)
  */
 static int Curl_ossl_init(void)
 {
-#ifdef ENABLE_SSLKEYLOGFILE
-  char *keylog_file_name;
-#endif
-
   OPENSSL_load_builtin_modules();
 
 #ifdef USE_OPENSSL_ENGINE
@@ -1199,26 +1129,7 @@ static int Curl_ossl_init(void)
   OpenSSL_add_all_algorithms();
 #endif
 
-#ifdef ENABLE_SSLKEYLOGFILE
-  if(!keylog_file_fp) {
-    keylog_file_name = curl_getenv("SSLKEYLOGFILE");
-    if(keylog_file_name) {
-      keylog_file_fp = fopen(keylog_file_name, FOPEN_APPENDTEXT);
-      if(keylog_file_fp) {
-#ifdef WIN32
-        if(setvbuf(keylog_file_fp, NULL, _IONBF, 0))
-#else
-        if(setvbuf(keylog_file_fp, NULL, _IOLBF, 4096))
-#endif
-        {
-          fclose(keylog_file_fp);
-          keylog_file_fp = NULL;
-        }
-      }
-      Curl_safefree(keylog_file_name);
-    }
-  }
-#endif
+  Curl_tls_keylog_open();
 
   /* Initialize the extra data indexes */
   if(ossl_get_ssl_conn_index() < 0 || ossl_get_ssl_sockindex_index() < 0)
@@ -1261,12 +1172,7 @@ static void Curl_ossl_cleanup(void)
 #endif
 #endif
 
-#ifdef ENABLE_SSLKEYLOGFILE
-  if(keylog_file_fp) {
-    fclose(keylog_file_fp);
-    keylog_file_fp = NULL;
-  }
-#endif
+  Curl_tls_keylog_close();
 }
 
 /*
@@ -3159,8 +3065,8 @@ static CURLcode ossl_connect_step1(struct connectdata *conn, int sockindex)
                      verifypeer ? SSL_VERIFY_PEER : SSL_VERIFY_NONE, NULL);
 
   /* Enable logging of secrets to the file specified in env SSLKEYLOGFILE. */
-#if defined(ENABLE_SSLKEYLOGFILE) && defined(HAVE_KEYLOG_CALLBACK)
-  if(keylog_file_fp) {
+#ifdef HAVE_KEYLOG_CALLBACK
+  if(Curl_tls_keylog_enabled()) {
     SSL_CTX_set_keylog_callback(backend->ctx, ossl_keylog_callback);
   }
 #endif
@@ -3283,10 +3189,13 @@ static CURLcode ossl_connect_step2(struct connectdata *conn, int sockindex)
   ERR_clear_error();
 
   err = SSL_connect(backend->handle);
-  /* If keylogging is enabled but the keylog callback is not supported then log
-     secrets here, immediately after SSL_connect by using tap_ssl_key. */
-#if defined(ENABLE_SSLKEYLOGFILE) && !defined(HAVE_KEYLOG_CALLBACK)
-  tap_ssl_key(backend->handle, &backend->tap_state);
+#ifndef HAVE_KEYLOG_CALLBACK
+  if(Curl_tls_keylog_enabled()) {
+    /* If key logging is enabled, wait for the handshake to complete and then
+     * proceed with logging secrets (for TLS 1.2 or older).
+     */
+    ossl_log_tls12_secret(backend->handle, &backend->keylog_done);
+  }
 #endif
 
   /* 1  is fine