Unverified Commit 84c10dc1 authored by Daniel Stenberg's avatar Daniel Stenberg
Browse files

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
parent aa1f1d48

lib/vtls/schannel.c

+77 −63
Original line number Diff line number Diff line
@@ -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 "

      DEBUGF(infof(data, "schannel: verifyhost setting prevents Schannel from "

                   "comparing the supplied target name with the subject "

            "names in server certificates.\n");

                   "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);

  }