From 84c10dc1ba683a2c15303ad3909e30a5a115a282 Mon Sep 17 00:00:00 2001 From: Daniel Stenberg Date: Mon, 11 Feb 2019 12:09:45 +0100 Subject: [PATCH] schannel: be quiet 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 Closes #3552 --- lib/vtls/schannel.c | 140 ++++++++++++++++++++++++-------------------- 1 file 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); }