schannel: be quietbagder/schannel-hush

Convert numerous infof() calls into debug-build only messages since they
are annoyingly verbose for regular applications. Removed a few.

Bug: https://curl.haxx.se/mail/lib-2019-02/0027.html
Reported-by: Volker Schmid

1 files changed, 77 insertions, 63 deletions

diff --git a/lib/vtls/schannel.c b/lib/vtls/schannel.c
index 7e5d19b20..8ae15baf9 100644
--- a/lib/vtls/schannel.c
+++ b/lib/vtls/schannel.c
@@ -433,8 +433,9 @@ schannel_connect_step1(struct connectdata *conn, int sockindex)
   char * const hostname = SSL_IS_PROXY() ? conn->http_proxy.host.name :
     conn->host.name;
 
-  infof(data, "schannel: SSL/TLS connection with %s port %hu (step 1/3)\n",
-        hostname, conn->remote_port);
+  DEBUGF(infof(data,
+               "schannel: SSL/TLS connection with %s port %hu (step 1/3)\n",
+               hostname, conn->remote_port));
 
   if(Curl_verify_windows_version(5, 1, PLATFORM_WINNT,
                                  VERSION_LESS_THAN_EQUAL)) {
@@ -494,12 +495,13 @@ schannel_connect_step1(struct connectdata *conn, int sockindex)
     Curl_ssl_sessionid_lock(conn);
     if(!Curl_ssl_getsessionid(conn, (void **)&old_cred, NULL, sockindex)) {
       BACKEND->cred = old_cred;
-      infof(data, "schannel: re-using existing credential handle\n");
+      DEBUGF(infof(data, "schannel: re-using existing credential handle\n"));
 
       /* increment the reference counter of the credential/session handle */
       BACKEND->cred->refcount++;
-      infof(data, "schannel: incremented credential handle refcount = %d\n",
-            BACKEND->cred->refcount);
+      DEBUGF(infof(data,
+                   "schannel: incremented credential handle refcount = %d\n",
+                   BACKEND->cred->refcount));
     }
     Curl_ssl_sessionid_unlock(conn);
   }
@@ -522,26 +524,28 @@ schannel_connect_step1(struct connectdata *conn, int sockindex)
         schannel_cred.dwFlags |= SCH_CRED_IGNORE_NO_REVOCATION_CHECK |
           SCH_CRED_IGNORE_REVOCATION_OFFLINE;
 
-        infof(data, "schannel: disabled server certificate revocation "
-                    "checks\n");
+        DEBUGF(infof(data, "schannel: disabled server certificate revocation "
+                     "checks\n"));
       }
       else {
         schannel_cred.dwFlags |= SCH_CRED_REVOCATION_CHECK_CHAIN;
-        infof(data, "schannel: checking server certificate revocation\n");
+        DEBUGF(infof(data,
+                     "schannel: checking server certificate revocation\n"));
       }
     }
     else {
       schannel_cred.dwFlags = SCH_CRED_MANUAL_CRED_VALIDATION |
         SCH_CRED_IGNORE_NO_REVOCATION_CHECK |
         SCH_CRED_IGNORE_REVOCATION_OFFLINE;
-      infof(data, "schannel: disabled server certificate revocation checks\n");
+      DEBUGF(infof(data,
+                   "schannel: disabled server cert revocation checks\n"));
     }
 
     if(!conn->ssl_config.verifyhost) {
       schannel_cred.dwFlags |= SCH_CRED_NO_SERVERNAME_CHECK;
-      infof(data, "schannel: verifyhost setting prevents Schannel from "
-            "comparing the supplied target name with the subject "
-            "names in server certificates.\n");
+      DEBUGF(infof(data, "schannel: verifyhost setting prevents Schannel from "
+                   "comparing the supplied target name with the subject "
+                   "names in server certificates.\n"));
     }
 
     switch(conn->ssl_config.version) {
@@ -824,8 +828,8 @@ schannel_connect_step1(struct connectdata *conn, int sockindex)
     }
   }
 
-  infof(data, "schannel: sending initial handshake data: "
-        "sending %lu bytes...\n", outbuf.cbBuffer);
+  DEBUGF(infof(data, "schannel: sending initial handshake data: "
+               "sending %lu bytes...\n", outbuf.cbBuffer));
 
   /* send initial handshake data which is now stored in output buffer */
   result = Curl_write_plain(conn, conn->sock[sockindex], outbuf.pvBuffer,
@@ -837,8 +841,8 @@ schannel_connect_step1(struct connectdata *conn, int sockindex)
     return CURLE_SSL_CONNECT_ERROR;
   }
 
-  infof(data, "schannel: sent initial handshake data: "
-        "sent %zd bytes\n", written);
+  DEBUGF(infof(data, "schannel: sent initial handshake data: "
+               "sent %zd bytes\n", written));
 
   BACKEND->recv_unrecoverable_err = CURLE_OK;
   BACKEND->recv_sspi_close_notify = false;
@@ -874,8 +878,9 @@ schannel_connect_step2(struct connectdata *conn, int sockindex)
 
   doread = (connssl->connecting_state != ssl_connect_2_writing) ? TRUE : FALSE;
 
-  infof(data, "schannel: SSL/TLS connection with %s port %hu (step 2/3)\n",
-        hostname, conn->remote_port);
+  DEBUGF(infof(data,
+               "schannel: SSL/TLS connection with %s port %hu (step 2/3)\n",
+               hostname, conn->remote_port));
 
   if(!BACKEND->cred || !BACKEND->ctxt)
     return CURLE_SSL_CONNECT_ERROR;
@@ -934,8 +939,8 @@ schannel_connect_step2(struct connectdata *conn, int sockindex)
       if(result == CURLE_AGAIN) {
         if(connssl->connecting_state != ssl_connect_2_writing)
           connssl->connecting_state = ssl_connect_2_reading;
-        infof(data, "schannel: failed to receive handshake, "
-              "need more data\n");
+        DEBUGF(infof(data, "schannel: failed to receive handshake, "
+                     "need more data\n"));
         return CURLE_OK;
       }
       else if((result != CURLE_OK) || (nread == 0)) {
@@ -947,11 +952,12 @@ schannel_connect_step2(struct connectdata *conn, int sockindex)
       /* increase encrypted data buffer offset */
       BACKEND->encdata_offset += nread;
       BACKEND->encdata_is_incomplete = false;
-      infof(data, "schannel: encrypted data got %zd\n", nread);
+      DEBUGF(infof(data, "schannel: encrypted data got %zd\n", nread));
     }
 
-    infof(data, "schannel: encrypted data buffer: offset %zu length %zu\n",
-          BACKEND->encdata_offset, BACKEND->encdata_length);
+    DEBUGF(infof(data,
+                 "schannel: encrypted data buffer: offset %zu length %zu\n",
+                 BACKEND->encdata_offset, BACKEND->encdata_length));
 
     /* setup input buffers */
     InitSecBuffer(&inbuf[0], SECBUFFER_TOKEN, malloc(BACKEND->encdata_offset),
@@ -994,7 +1000,8 @@ schannel_connect_step2(struct connectdata *conn, int sockindex)
     if(sspi_status == SEC_E_INCOMPLETE_MESSAGE) {
       BACKEND->encdata_is_incomplete = true;
       connssl->connecting_state = ssl_connect_2_reading;
-      infof(data, "schannel: received incomplete message, need more data\n");
+      DEBUGF(infof(data,
+                   "schannel: received incomplete message, need more data\n"));
       return CURLE_OK;
     }
 
@@ -1005,7 +1012,8 @@ schannel_connect_step2(struct connectdata *conn, int sockindex)
        !(BACKEND->req_flags & ISC_REQ_USE_SUPPLIED_CREDS)) {
       BACKEND->req_flags |= ISC_REQ_USE_SUPPLIED_CREDS;
       connssl->connecting_state = ssl_connect_2_writing;
-      infof(data, "schannel: a client certificate has been requested\n");
+      DEBUGF(infof(data,
+                   "schannel: a client certificate has been requested\n"));
       return CURLE_OK;
     }
 
@@ -1014,8 +1022,8 @@ schannel_connect_step2(struct connectdata *conn, int sockindex)
       for(i = 0; i < 3; i++) {
         /* search for handshake tokens that need to be send */
         if(outbuf[i].BufferType == SECBUFFER_TOKEN && outbuf[i].cbBuffer > 0) {
-          infof(data, "schannel: sending next handshake data: "
-                "sending %lu bytes...\n", outbuf[i].cbBuffer);
+          DEBUGF(infof(data, "schannel: sending next handshake data: "
+                       "sending %lu bytes...\n", outbuf[i].cbBuffer));
 
           /* send handshake token to server */
           result = Curl_write_plain(conn, conn->sock[sockindex],
@@ -1065,7 +1073,8 @@ schannel_connect_step2(struct connectdata *conn, int sockindex)
 
     /* check if there was additional remaining encrypted data */
     if(inbuf[1].BufferType == SECBUFFER_EXTRA && inbuf[1].cbBuffer > 0) {
-      infof(data, "schannel: encrypted data length: %lu\n", inbuf[1].cbBuffer);
+      DEBUGF(infof(data, "schannel: encrypted data length: %lu\n",
+                   inbuf[1].cbBuffer));
       /*
         There are two cases where we could be getting extra data here:
         1) If we're renegotiating a connection and the handshake is already
@@ -1104,7 +1113,7 @@ schannel_connect_step2(struct connectdata *conn, int sockindex)
   /* check if the handshake is complete */
   if(sspi_status == SEC_E_OK) {
     connssl->connecting_state = ssl_connect_3;
-    infof(data, "schannel: SSL/TLS handshake complete\n");
+    DEBUGF(infof(data, "schannel: SSL/TLS handshake complete\n"));
   }
 
   pubkey_ptr = SSL_IS_PROXY() ?
@@ -1190,7 +1199,7 @@ schannel_connect_step3(struct connectdata *conn, int sockindex)
   struct ssl_connect_data *connssl = &conn->ssl[sockindex];
   SECURITY_STATUS sspi_status = SEC_E_OK;
   CERT_CONTEXT *ccert_context = NULL;
-#ifndef CURL_DISABLE_VERBOSE_STRINGS
+#ifdef DEBUGBUILD
   const char * const hostname = SSL_IS_PROXY() ? conn->http_proxy.host.name :
     conn->host.name;
 #endif
@@ -1200,8 +1209,9 @@ schannel_connect_step3(struct connectdata *conn, int sockindex)
 
   DEBUGASSERT(ssl_connect_3 == connssl->connecting_state);
 
-  infof(data, "schannel: SSL/TLS connection with %s port %hu (step 3/3)\n",
-        hostname, conn->remote_port);
+  DEBUGF(infof(data,
+               "schannel: SSL/TLS connection with %s port %hu (step 3/3)\n",
+               hostname, conn->remote_port));
 
   if(!BACKEND->cred)
     return CURLE_SSL_CONNECT_ERROR;
@@ -1266,7 +1276,8 @@ schannel_connect_step3(struct connectdata *conn, int sockindex)
                                       sockindex));
     if(incache) {
       if(old_cred != BACKEND->cred) {
-        infof(data, "schannel: old credential handle is stale, removing\n");
+        DEBUGF(infof(data,
+                     "schannel: old credential handle is stale, removing\n"));
         /* we're not taking old_cred ownership here, no refcount++ is needed */
         Curl_ssl_delsessionid(conn, (void *)old_cred);
         incache = FALSE;
@@ -1284,7 +1295,8 @@ schannel_connect_step3(struct connectdata *conn, int sockindex)
       else {
         /* this cred session is now also referenced by sessionid cache */
         BACKEND->cred->refcount++;
-        infof(data, "schannel: stored credential handle in session cache\n");
+        DEBUGF(infof(data,
+                     "schannel: stored credential handle in session cache\n"));
       }
     }
     Curl_ssl_sessionid_unlock(conn);
@@ -1615,7 +1627,6 @@ schannel_recv(struct connectdata *conn, int sockindex,
    * handled in the cleanup.
    */
 
-  infof(data, "schannel: client wants to read %zu bytes\n", len);
   *err = CURLE_OK;
 
   if(len && len <= BACKEND->decdata_offset) {
@@ -1660,12 +1671,13 @@ schannel_recv(struct connectdata *conn, int sockindex,
       BACKEND->encdata_buffer = reallocated_buffer;
       BACKEND->encdata_length = reallocated_length;
       size = BACKEND->encdata_length - BACKEND->encdata_offset;
-      infof(data, "schannel: encdata_buffer resized %zu\n",
-            BACKEND->encdata_length);
+      DEBUGF(infof(data, "schannel: encdata_buffer resized %zu\n",
+                   BACKEND->encdata_length));
     }
 
-    infof(data, "schannel: encrypted data buffer: offset %zu length %zu\n",
-          BACKEND->encdata_offset, BACKEND->encdata_length);
+    DEBUGF(infof(data,
+                 "schannel: encrypted data buffer: offset %zu length %zu\n",
+                 BACKEND->encdata_offset, BACKEND->encdata_length));
 
     /* read encrypted data from socket */
     *err = Curl_read_plain(conn->sock[sockindex],
@@ -1675,7 +1687,7 @@ schannel_recv(struct connectdata *conn, int sockindex,
     if(*err) {
       nread = -1;
       if(*err == CURLE_AGAIN)
-        infof(data, "schannel: Curl_read_plain returned CURLE_AGAIN\n");
+        ;
       else if(*err == CURLE_RECV_ERROR)
         infof(data, "schannel: Curl_read_plain returned CURLE_RECV_ERROR\n");
       else
@@ -1683,17 +1695,18 @@ schannel_recv(struct connectdata *conn, int sockindex,
     }
     else if(nread == 0) {
       BACKEND->recv_connection_closed = true;
-      infof(data, "schannel: server closed the connection\n");
+      DEBUGF(infof(data, "schannel: server closed the connection\n"));
     }
     else if(nread > 0) {
       BACKEND->encdata_offset += (size_t)nread;
       BACKEND->encdata_is_incomplete = false;
-      infof(data, "schannel: encrypted data got %zd\n", nread);
+      DEBUGF(infof(data, "schannel: encrypted data got %zd\n", nread));
     }
   }
 
-  infof(data, "schannel: encrypted data buffer: offset %zu length %zu\n",
-        BACKEND->encdata_offset, BACKEND->encdata_length);
+  DEBUGF(infof(data,
+               "schannel: encrypted data buffer: offset %zu length %zu\n",
+               BACKEND->encdata_offset, BACKEND->encdata_length));
 
   /* decrypt loop */
   while(BACKEND->encdata_offset > 0 && sspi_status == SEC_E_OK &&
@@ -1721,8 +1734,6 @@ schannel_recv(struct connectdata *conn, int sockindex,
       /* check for successfully decrypted data, even before actual
          renegotiation or shutdown of the connection context */
       if(inbuf[1].BufferType == SECBUFFER_DATA) {
-        infof(data, "schannel: decrypted data length: %lu\n",
-              inbuf[1].cbBuffer);
 
         /* increase buffer in order to fit the received amount of data */
         size = inbuf[1].cbBuffer > CURL_SCHANNEL_BUFFER_FREE_SIZE ?
@@ -1754,15 +1765,16 @@ schannel_recv(struct connectdata *conn, int sockindex,
           BACKEND->decdata_offset += size;
         }
 
-        infof(data, "schannel: decrypted data added: %zu\n", size);
-        infof(data, "schannel: decrypted data cached: offset %zu length %zu\n",
-              BACKEND->decdata_offset, BACKEND->decdata_length);
+        DEBUGF(infof(data, "schannel: decrypted data added: %zu\n", size));
+        DEBUGF(infof(data,
+                     "schannel: decrypted cached: offset %zu length %zu\n",
+                     BACKEND->decdata_offset, BACKEND->decdata_length));
       }
 
       /* check for remaining encrypted data */
       if(inbuf[3].BufferType == SECBUFFER_EXTRA && inbuf[3].cbBuffer > 0) {
-        infof(data, "schannel: encrypted data length: %lu\n",
-              inbuf[3].cbBuffer);
+        DEBUGF(infof(data, "schannel: encrypted data length: %lu\n",
+                     inbuf[3].cbBuffer));
 
         /* check if the remaining data is less than the total amount
          * and therefore begins after the already processed data
@@ -1776,8 +1788,9 @@ schannel_recv(struct connectdata *conn, int sockindex,
           BACKEND->encdata_offset = inbuf[3].cbBuffer;
         }
 
-        infof(data, "schannel: encrypted data cached: offset %zu length %zu\n",
-              BACKEND->encdata_offset, BACKEND->encdata_length);
+        DEBUGF(infof(data,
+                     "schannel: encrypted cached: offset %zu length %zu\n",
+                     BACKEND->encdata_offset, BACKEND->encdata_length));
       }
       else {
         /* reset encrypted buffer offset, because there is no data remaining */
@@ -1838,15 +1851,17 @@ schannel_recv(struct connectdata *conn, int sockindex,
     }
   }
 
-  infof(data, "schannel: encrypted data buffer: offset %zu length %zu\n",
-        BACKEND->encdata_offset, BACKEND->encdata_length);
+  DEBUGF(infof(data,
+               "schannel: encrypted data buffer: offset %zu length %zu\n",
+               BACKEND->encdata_offset, BACKEND->encdata_length));
 
-  infof(data, "schannel: decrypted data buffer: offset %zu length %zu\n",
-        BACKEND->decdata_offset, BACKEND->decdata_length);
+  DEBUGF(infof(data,
+               "schannel: decrypted data buffer: offset %zu length %zu\n",
+               BACKEND->decdata_offset, BACKEND->decdata_length));
 
 cleanup:
   /* Warning- there is no guarantee the encdata state is valid at this point */
-  infof(data, "schannel: schannel_recv cleanup\n");
+  DEBUGF(infof(data, "schannel: schannel_recv cleanup\n"));
 
   /* Error if the connection has closed without a close_notify.
   Behavior here is a matter of debate. We don't want to be vulnerable to a
@@ -1879,10 +1894,10 @@ cleanup:
     memmove(BACKEND->decdata_buffer, BACKEND->decdata_buffer + size,
             BACKEND->decdata_offset - size);
     BACKEND->decdata_offset -= size;
-
-    infof(data, "schannel: decrypted data returned %zu\n", size);
-    infof(data, "schannel: decrypted data buffer: offset %zu length %zu\n",
-          BACKEND->decdata_offset, BACKEND->decdata_length);
+    DEBUGF(infof(data, "schannel: decrypted data returned %zu\n", size));
+    DEBUGF(infof(data,
+                 "schannel: decrypted data buffer: offset %zu length %zu\n",
+                 BACKEND->decdata_offset, BACKEND->decdata_length));
     *err = CURLE_OK;
     return (ssize_t)size;
   }
@@ -2025,7 +2040,6 @@ static int Curl_schannel_shutdown(struct connectdata *conn, int sockindex)
 
   /* free SSPI Schannel API security context handle */
   if(BACKEND->ctxt) {
-    infof(data, "schannel: clear security context handle\n");
     s_pSecFn->DeleteSecurityContext(&BACKEND->ctxt->ctxt_handle);
     Curl_safefree(BACKEND->ctxt);
   }