Bug 1312977 - Improve tracing for TLS 1.3, r=ekr
authorMartin Thomson <martin.thomson@gmail.com>
Fri, 21 Oct 2016 11:00:56 +1100
changeset 12771 8131d772968bd84e143782c0e549f89b38417920
parent 12770 b7b419e4e2f6c7bdda9700ac37883dec5e1ddef8
child 12772 3224146ec4c4e097cd354c48bdd782ed04996171
push id1713
push usermartin.thomson@gmail.com
push dateThu, 27 Oct 2016 03:16:34 +0000
reviewersekr
bugs1312977
Bug 1312977 - Improve tracing for TLS 1.3, r=ekr
lib/ssl/ssl3ecc.c
lib/ssl/sslgrp.c
lib/ssl/sslimpl.h
lib/ssl/ssltrace.c
lib/ssl/tls13con.c
--- a/lib/ssl/ssl3ecc.c
+++ b/lib/ssl/ssl3ecc.c
@@ -190,17 +190,17 @@ ssl3_SendECDHClientKeyExchange(sslSocket
         goto loser;
     }
     groupDef = ssl_ECPubKey2NamedGroup(svrPubKey);
     if (!groupDef) {
         PORT_SetError(SEC_ERROR_BAD_KEY);
         goto loser;
     }
     ss->sec.keaGroup = groupDef;
-    rv = ssl_CreateECDHEphemeralKeyPair(groupDef, &keyPair);
+    rv = ssl_CreateECDHEphemeralKeyPair(ss, groupDef, &keyPair);
     if (rv != SECSuccess) {
         ssl_MapLowLevelError(SEC_ERROR_KEYGEN_FAIL);
         goto loser;
     }
 
     pubKey = keyPair->keys->pubKey;
     PRINT_BUF(50, (ss, "ECDH public value:",
                    pubKey->u.ec.publicValue.data,
@@ -468,17 +468,18 @@ ssl_GetECGroupForServerSocket(sslSocket 
         requiredECCbits = certKeySize;
     }
 
     return ssl_GetECGroupWithStrength(ss, requiredECCbits);
 }
 
 /* Create an ECDHE key pair for a given curve */
 SECStatus
-ssl_CreateECDHEphemeralKeyPair(const sslNamedGroupDef *ecGroup,
+ssl_CreateECDHEphemeralKeyPair(const sslSocket *ss,
+                               const sslNamedGroupDef *ecGroup,
                                sslEphemeralKeyPair **keyPair)
 {
     SECKEYPrivateKey *privKey = NULL;
     SECKEYPublicKey *pubKey = NULL;
     SECKEYECParams ecParams = { siBuffer, NULL, 0 };
     sslEphemeralKeyPair *pair;
 
     if (ssl_NamedGroup2ECParams(NULL, ecGroup, &ecParams) != SECSuccess) {
@@ -495,16 +496,33 @@ ssl_CreateECDHEphemeralKeyPair(const ssl
         if (pubKey) {
             SECKEY_DestroyPublicKey(pubKey);
         }
         ssl_MapLowLevelError(SEC_ERROR_KEYGEN_FAIL);
         return SECFailure;
     }
 
     *keyPair = pair;
+    SSL_TRC(50, ("%d: SSL[%d]: Create ECDH ephemeral key %d",
+                 SSL_GETPID(), ss ? ss->fd : NULL, ecGroup->name));
+    PRINT_BUF(50, (ss, "Public Key", pubKey->u.ec.publicValue.data,
+                   pubKey->u.ec.publicValue.len));
+#ifdef TRACE
+    if (ssl_trace >= 50) {
+        SECItem d = {siBuffer, NULL, 0};
+        SECStatus rv = PK11_ReadRawAttribute(PK11_TypePrivKey, privKey,
+                                             CKA_VALUE, &d);
+        if (rv == SECSuccess) {
+            PRINT_BUF(50, (ss, "Private Key", d.data, d.len));
+            SECITEM_FreeItem(&d, PR_FALSE);
+        } else {
+            SSL_TRC(50, ("Error extracting private key"));
+        }
+    }
+#endif
     return SECSuccess;
 }
 
 SECStatus
 ssl3_HandleECDHServerKeyExchange(sslSocket *ss, SSL3Opaque *b, PRUint32 length)
 {
     PLArenaPool *arena = NULL;
     SECKEYPublicKey *peerKey = NULL;
@@ -682,17 +700,17 @@ ssl3_SendECDHServerKeyExchange(sslSocket
     PORT_Assert(PR_CLIST_IS_EMPTY(&ss->ephemeralKeyPairs));
     if (ss->opt.reuseServerECDHEKey) {
         rv = ssl_CreateStaticECDHEKey(ss, ecGroup);
         if (rv != SECSuccess) {
             goto loser;
         }
         keyPair = (sslEphemeralKeyPair *)PR_NEXT_LINK(&ss->ephemeralKeyPairs);
     } else {
-        rv = ssl_CreateECDHEphemeralKeyPair(ecGroup, &keyPair);
+        rv = ssl_CreateECDHEphemeralKeyPair(ss, ecGroup, &keyPair);
         if (rv != SECSuccess) {
             goto loser;
         }
         PR_APPEND_LINK(&keyPair->link, &ss->ephemeralKeyPairs);
     }
 
     PORT_Assert(keyPair);
     if (!keyPair) {
--- a/lib/ssl/sslgrp.c
+++ b/lib/ssl/sslgrp.c
@@ -49,17 +49,18 @@ static PRStatus
 ssl_CreateStaticECDHEKeyPair(void *arg)
 {
     const sslNamedGroupDef *group = (const sslNamedGroupDef *)arg;
     unsigned int i = group - ssl_named_groups;
     SECStatus rv;
 
     PORT_Assert(group->keaType == ssl_kea_ecdh);
     PORT_Assert(i < SSL_NAMED_GROUP_COUNT);
-    rv = ssl_CreateECDHEphemeralKeyPair(group, &gECDHEKeyPairs[i].keyPair);
+    rv = ssl_CreateECDHEphemeralKeyPair(NULL, group,
+                                        &gECDHEKeyPairs[i].keyPair);
     if (rv != SECSuccess) {
         gECDHEKeyPairs[i].keyPair = NULL;
         SSL_TRC(5, ("%d: SSL[-]: disabling group %d",
                     SSL_GETPID(), group->name));
     }
 
     return PR_SUCCESS;
 }
--- a/lib/ssl/sslimpl.h
+++ b/lib/ssl/sslimpl.h
@@ -1136,16 +1136,19 @@ struct sslConnectInfoStr {
 
 /* Note: The entire content of this struct and whatever it points to gets
  * blown away by SSL_ResetHandshake().  This is "sec" as in "ss->sec".
  *
  * Unless otherwise specified below, the contents of this struct are
  * protected by firstHandshakeLock AND ssl3HandshakeLock.
  */
 struct sslSecurityInfoStr {
+
+#define SSL_ROLE(ss) (ss->sec.isServer ? "server" : "client")
+
     PRBool isServer;
     sslBuffer writeBuf; /*xmitBufLock*/
 
     CERTCertificate *localCert;
     CERTCertificate *peerCert;
     SECKEYPublicKey *peerKey;
 
     SSLAuthType authType;
@@ -1395,18 +1398,19 @@ extern SECStatus ssl3_InitGather(sslGath
 extern void ssl3_DestroyGather(sslGather *gs);
 extern SECStatus ssl_GatherRecord1stHandshake(sslSocket *ss);
 
 extern SECStatus ssl_CreateSecurityInfo(sslSocket *ss);
 extern SECStatus ssl_CopySecurityInfo(sslSocket *ss, sslSocket *os);
 extern void ssl_ResetSecurityInfo(sslSecurityInfo *sec, PRBool doMemset);
 extern void ssl_DestroySecurityInfo(sslSecurityInfo *sec);
 
-extern void ssl_PrintBuf(sslSocket *ss, const char *msg, const void *cp, int len);
-extern void ssl_PrintKey(sslSocket *ss, const char *msg, PK11SymKey *key);
+extern void ssl_PrintBuf(const sslSocket *ss, const char *msg, const void *cp,
+                         int len);
+extern void ssl_PrintKey(const sslSocket *ss, const char *msg, PK11SymKey *key);
 
 extern int ssl_SendSavedWriteData(sslSocket *ss);
 extern SECStatus ssl_SaveWriteData(sslSocket *ss,
                                    const void *p, unsigned int l);
 extern SECStatus ssl_BeginClientHandshake(sslSocket *ss);
 extern SECStatus ssl_BeginServerHandshake(sslSocket *ss);
 extern int ssl_Do1stHandshake(sslSocket *ss);
 
@@ -1948,17 +1952,18 @@ SECStatus ssl3_CompleteHandleCertificate
     unsigned int signatureSchemeCount, CERTDistNames *ca_list);
 SECStatus ssl3_SendServerHello(sslSocket *ss);
 SECStatus ssl3_ComputeHandshakeHashes(sslSocket *ss,
                                       ssl3CipherSpec *spec,
                                       SSL3Hashes *hashes,
                                       PRUint32 sender);
 PRInt32 tls13_ServerSendKeyShareXtn(sslSocket *ss, PRBool append,
                                     PRUint32 maxBytes);
-SECStatus ssl_CreateECDHEphemeralKeyPair(const sslNamedGroupDef *ecGroup,
+SECStatus ssl_CreateECDHEphemeralKeyPair(const sslSocket *ss,
+                                         const sslNamedGroupDef *ecGroup,
                                          sslEphemeralKeyPair **keyPair);
 SECStatus ssl_CreateStaticECDHEKey(sslSocket *ss,
                                    const sslNamedGroupDef *ecGroup);
 SECStatus ssl3_FlushHandshake(sslSocket *ss, PRInt32 flags);
 PK11SymKey *ssl3_GetWrappingKey(sslSocket *ss,
                                 PK11SlotInfo *masterSecretSlot,
                                 const sslServerCert *serverCert,
                                 CK_MECHANISM_TYPE masterWrapMech,
--- a/lib/ssl/ssltrace.c
+++ b/lib/ssl/ssltrace.c
@@ -30,17 +30,17 @@ static const char printable[257] = {
     "................"  /* bx */
     "................"  /* cx */
     "................"  /* dx */
     "................"  /* ex */
     "................"  /* fx */
 };
 
 void
-ssl_PrintBuf(sslSocket *ss, const char *msg, const void *vp, int len)
+ssl_PrintBuf(const sslSocket *ss, const char *msg, const void *vp, int len)
 {
     const unsigned char *cp = (const unsigned char *)vp;
     char buf[80];
     char *bp;
     char *ap;
 
     if (ss) {
         SSL_TRACE(("%d: SSL[%d]: %s [Len: %d]", SSL_GETPID(), ss->fd,
@@ -89,17 +89,17 @@ ssl_Trace(const char *format, ...)
         va_end(args);
 
         fputs(buf, ssl_trace_iob);
         fputs("\n", ssl_trace_iob);
     }
 }
 
 void
-ssl_PrintKey(sslSocket *ss, const char *msg, PK11SymKey *key)
+ssl_PrintKey(const sslSocket *ss, const char *msg, PK11SymKey *key)
 {
     SECStatus rv;
     SECItem *rawkey;
 
     rv = PK11_ExtractKeyValue(key);
     if (rv != SECSuccess) {
         ssl_Trace("Could not extract key for %s", msg);
         return;
--- a/lib/ssl/tls13con.c
+++ b/lib/ssl/tls13con.c
@@ -197,18 +197,17 @@ void
 tls13_SetHsState(sslSocket *ss, SSL3WaitState ws,
                  const char *func, const char *file, int line)
 {
 #ifdef TRACE
     const char *new_state_name =
         tls13_HandshakeState(ws);
 
     SSL_TRC(3, ("%d: TLS13[%d]: %s state change from %s->%s in %s (%s:%d)",
-                SSL_GETPID(), ss->fd,
-                ss->sec.isServer ? "server" : "client",
+                SSL_GETPID(), ss->fd, SSL_ROLE(ss),
                 tls13_HandshakeState(TLS13_BASE_WAIT_STATE(ss->ssl3.hs.ws)),
                 new_state_name,
                 func, file, line));
 #endif
 
     ss->ssl3.hs.ws = TLS13_WAIT_STATE(ws);
 }
 
@@ -327,17 +326,17 @@ tls13_CreateKeyShare(sslSocket *ss, cons
 {
     SECStatus rv;
     sslEphemeralKeyPair *keyPair = NULL;
     const ssl3DHParams *params;
 
     PORT_Assert(groupDef);
     switch (groupDef->keaType) {
         case ssl_kea_ecdh:
-            rv = ssl_CreateECDHEphemeralKeyPair(groupDef, &keyPair);
+            rv = ssl_CreateECDHEphemeralKeyPair(ss, groupDef, &keyPair);
             if (rv != SECSuccess) {
                 return SECFailure;
             }
             break;
         case ssl_kea_dh:
             params = ssl_GetDHEParams(groupDef);
             PORT_Assert(params->name != ssl_grp_ffdhe_custom);
             rv = ssl_CreateDHEKeyPair(groupDef, params, &keyPair);
@@ -584,18 +583,17 @@ tls13_RecoverWrappedSharedSecret(sslSock
     PK11SymKey *wrapKey; /* wrapping key */
     PK11SymKey *RMS = NULL;
     SECItem wrappedMS = { siBuffer, NULL, 0 };
     SSLHashType hashType;
     const ssl3CipherSuiteDef *cipherDef;
     SECStatus rv;
 
     SSL_TRC(3, ("%d: TLS13[%d]: recovering static secret (%s)",
-                SSL_GETPID(), ss->fd,
-                ss->sec.isServer ? "server" : "client"));
+                SSL_GETPID(), ss->fd, SSL_ROLE(ss)));
     if (!sid->u.ssl3.keys.msIsWrapped) {
         PORT_Assert(0); /* I think this can't happen. */
         return SECFailure;
     }
 
     /* Now find the hash used as the PRF for the previous handshake. */
     cipherDef = ssl_LookupCipherSuiteDef(sid->u.ssl3.cipherSuite);
     PORT_Assert(cipherDef);
@@ -744,16 +742,19 @@ loser:
 static SECStatus
 tls13_ComputeEarlySecrets(sslSocket *ss, PRBool setup0Rtt)
 {
     SECStatus rv = SECSuccess;
     PK11Context *ctx;
     PRUint8 hash[HASH_LENGTH_MAX];
     unsigned int len;
 
+    SSL_TRC(5, ("%d: TLS13[%d]: compute early secrets (%s)",
+                SSL_GETPID(), ss->fd, SSL_ROLE(ss)));
+
     /* Extract off the resumptionPsk (if present), else pass the NULL
      * resumptionPsk which will be internally translated to zeroes. */
     PORT_Assert(!ss->ssl3.hs.currentSecret);
     rv = tls13_HkdfExtract(NULL, ss->ssl3.hs.resumptionPsk,
                            tls13_GetHash(ss), &ss->ssl3.hs.currentSecret);
     if (rv != SECSuccess) {
         return SECFailure;
     }
@@ -818,16 +819,19 @@ tls13_ComputeEarlySecrets(sslSocket *ss,
 }
 
 static SECStatus
 tls13_ComputeHandshakeSecrets(sslSocket *ss)
 {
     SECStatus rv;
     PK11SymKey *newSecret = NULL;
 
+    SSL_TRC(5, ("%d: TLS13[%d]: compute handshake secrets (%s)",
+                SSL_GETPID(), ss->fd, SSL_ROLE(ss)));
+
     /* First update |currentSecret| to add |dheSecret|, if any. */
     PORT_Assert(ss->ssl3.hs.currentSecret);
     PORT_Assert(ss->ssl3.hs.dheSecret);
     rv = tls13_HkdfExtract(ss->ssl3.hs.currentSecret, ss->ssl3.hs.dheSecret,
                            tls13_GetHash(ss), &newSecret);
     if (rv != SECSuccess) {
         LOG_ERROR(ss, SEC_ERROR_LIBRARY_FAILURE);
         return rv;
@@ -850,16 +854,19 @@ tls13_ComputeHandshakeSecrets(sslSocket 
                             kHkdfLabelServer,
                             kHkdfLabelHandshakeTrafficSecret, NULL,
                             &ss->ssl3.hs.serverHsTrafficSecret);
     if (rv != SECSuccess) {
         LOG_ERROR(ss, SEC_ERROR_LIBRARY_FAILURE);
         return rv;
     }
 
+    SSL_TRC(5, ("%d: TLS13[%d]: compute master secret (%s)",
+                SSL_GETPID(), ss->fd, SSL_ROLE(ss)));
+
     /* Crank HKDF forward to make master secret, which we
      * stuff in current secret. */
     rv = tls13_HkdfExtract(ss->ssl3.hs.currentSecret,
                            NULL,
                            tls13_GetHash(ss),
                            &newSecret);
 
     if (rv != SECSuccess) {
@@ -1141,16 +1148,18 @@ tls13_NegotiateKeyExchange(sslSocket *ss
             }
         }
     }
 
     if (!preferredGroup) {
         FATAL_ERROR(ss, SSL_ERROR_NO_CYPHER_OVERLAP, handshake_failure);
         return SECFailure;
     }
+    SSL_TRC(3, ("%d: TLS13[%d]: group = %d", SSL_GETPID(), ss->fd,
+                preferredGroup->name));
 
     SSL_TRC(3, ("%d: TLS13[%d]: group = %d", preferredGroup->name));
 
     if (!entry) {
         return tls13_SendHelloRetryRequest(ss, preferredGroup);
     }
 
     PORT_Assert(preferredGroup == entry->group);
@@ -2569,18 +2578,17 @@ tls13_SetCipherSpec(sslSocket *ss, Traff
 
     /* Now that we've set almost everything up, finally cut over. */
     ssl_GetSpecWriteLock(ss);
     tls13_CipherSpecRelease(*specp); /* May delete old cipher. */
     *specp = spec;                   /* Overwrite. */
     ssl_ReleaseSpecWriteLock(ss);
 
     SSL_TRC(3, ("%d: TLS13[%d]: %s installed key for phase='%s'.%d dir=%s",
-                SSL_GETPID(), ss->fd,
-                ss->sec.isServer ? "server" : "client",
+                SSL_GETPID(), ss->fd, SSL_ROLE(ss),
                 spec->phase, spec->epoch,
                 direction == CipherSpecRead ? "read" : "write"));
 
     return SECSuccess;
 }
 
 static void
 tls13_CombineHashes(sslSocket *ss, const PRUint8 *hhash,