[log] Reduce log spam from security (#37296)

Split off from https://github.com/grpc/grpc/pull/37253.

These logs are from the security codebase, and we don't expect to see them during normal execution, so I'm not super concerned about these, but I'd still like to get to a point where we don't have any `LOG(INFO)` statements that are not guarded by a TraceFlag. So, if any of these logs are logs that we want enabled by default, I think we should do one of -
* move them to `LOG(ERROR)`
* protect them by a TraceFlag that is enabled by default. (This would still allow users to easily disable them.)

Closes #37296

COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/37296 from yashykt:SecurityLogSpan ea1c7718da
PiperOrigin-RevId: 655450344

src/core/lib/security/credentials/alts/check_gcp_environment.cc

@@ -58,7 +58,7 @@ namespace internal {
 char* read_bios_file(const char* bios_file) {
   FILE* fp = fopen(bios_file, "r");
   if (!fp) {
-    LOG(INFO) << "BIOS data file does not exist or cannot be opened.";
+    VLOG(2) << "BIOS data file does not exist or cannot be opened.";
     return nullptr;
   }
   char buf[kBiosDataBufferSize + 1];

src/core/lib/security/credentials/alts/check_gcp_environment_no_op.cc

@@ -26,7 +26,7 @@
 #include "src/core/lib/security/credentials/alts/check_gcp_environment.h"
 
 bool grpc_alts_is_running_on_gcp() {
-  LOG(INFO) << "ALTS: Platforms other than Linux and Windows are not supported";
+  VLOG(2) << "ALTS: Platforms other than Linux and Windows are not supported";
   return false;
 }
 

src/core/lib/security/credentials/jwt/json_token.cc

@@ -190,7 +190,7 @@ static char* encoded_jwt_claim(const grpc_auth_json_key* json_key,
   gpr_timespec now = gpr_now(GPR_CLOCK_REALTIME);
   gpr_timespec expiration = gpr_time_add(now, token_lifetime);
   if (gpr_time_cmp(token_lifetime, grpc_max_auth_token_lifetime()) > 0) {
-    LOG(INFO) << "Cropping token lifetime to maximum allowed value.";
+    VLOG(2) << "Cropping token lifetime to maximum allowed value.";
     expiration = gpr_time_add(now, grpc_max_auth_token_lifetime());
   }
 

src/core/lib/security/credentials/jwt/jwt_credentials.cc

@@ -115,8 +115,8 @@ grpc_service_account_jwt_access_credentials::
     : key_(key) {
   gpr_timespec max_token_lifetime = grpc_max_auth_token_lifetime();
   if (gpr_time_cmp(token_lifetime, max_token_lifetime) > 0) {
-    LOG(INFO) << "Cropping token lifetime to maximum allowed value ("
-              << max_token_lifetime.tv_sec << " secs).";
+    VLOG(2) << "Cropping token lifetime to maximum allowed value ("
+            << max_token_lifetime.tv_sec << " secs).";
     token_lifetime = grpc_max_auth_token_lifetime();
   }
   jwt_lifetime_ = token_lifetime;
@@ -155,13 +155,12 @@ grpc_call_credentials* grpc_service_account_jwt_access_credentials_create(
     const char* json_key, gpr_timespec token_lifetime, void* reserved) {
   if (GRPC_TRACE_FLAG_ENABLED(api)) {
     char* clean_json = redact_private_key(json_key);
-    LOG(INFO) << "grpc_service_account_jwt_access_credentials_create("
-              << "json_key=" << clean_json
-              << ", token_lifetime=gpr_timespec { tv_sec: "
-              << token_lifetime.tv_sec
-              << ", tv_nsec: " << token_lifetime.tv_nsec
-              << ", clock_type: " << token_lifetime.clock_type
-              << " }, reserved=" << reserved << ")";
+    VLOG(2) << "grpc_service_account_jwt_access_credentials_create("
+            << "json_key=" << clean_json
+            << ", token_lifetime=gpr_timespec { tv_sec: "
+            << token_lifetime.tv_sec << ", tv_nsec: " << token_lifetime.tv_nsec
+            << ", clock_type: " << token_lifetime.clock_type
+            << " }, reserved=" << reserved << ")";
     gpr_free(clean_json);
   }
   CHECK_EQ(reserved, nullptr);

src/core/lib/security/credentials/tls/grpc_tls_certificate_provider.cc

@@ -122,9 +122,9 @@ FileWatcherCertificateProvider::FileWatcherCertificateProvider(
       refresh_interval_sec_(refresh_interval_sec),
       distributor_(MakeRefCounted<grpc_tls_certificate_distributor>()) {
   if (refresh_interval_sec_ < kMinimumFileWatcherRefreshIntervalSeconds) {
-    LOG(INFO) << "FileWatcherCertificateProvider refresh_interval_sec_ set to "
-                 "value less than minimum. Overriding configured value to "
-                 "minimum.";
+    VLOG(2) << "FileWatcherCertificateProvider refresh_interval_sec_ set to "
+               "value less than minimum. Overriding configured value to "
+               "minimum.";
     refresh_interval_sec_ = kMinimumFileWatcherRefreshIntervalSeconds;
   }
   // Private key and identity cert files must be both set or both unset.

src/core/lib/security/credentials/tls/grpc_tls_credentials_options.cc

@@ -127,10 +127,9 @@ void grpc_tls_credentials_options_set_tls_session_key_log_file_path(
   // Tls session key logging is assumed to be enabled if the specified log
   // file is non-empty.
   if (path != nullptr) {
-    LOG(INFO) << "Enabling TLS session key logging with keys stored at: "
-              << path;
+    VLOG(2) << "Enabling TLS session key logging with keys stored at: " << path;
   } else {
-    LOG(INFO) << "Disabling TLS session key logging";
+    VLOG(2) << "Disabling TLS session key logging";
   }
   options->set_tls_session_key_log_file_path(path != nullptr ? path : "");
 }

src/core/lib/security/credentials/tls/tls_credentials.cc

@@ -84,8 +84,8 @@ bool CredentialOptionSanityCheck(grpc_tls_credentials_options* options,
     // If no verifier is specified on the client side, use the hostname verifier
     // as default. Users who want to bypass all the verifier check should
     // implement an external verifier instead.
-    LOG(INFO) << "No verifier specified on the client side. Using default "
-                 "hostname verifier";
+    VLOG(2) << "No verifier specified on the client side. Using default "
+               "hostname verifier";
     options->set_certificate_verifier(
         grpc_core::MakeRefCounted<grpc_core::HostNameCertificateVerifier>());
   }

src/core/lib/security/security_connector/ssl_utils.cc

@@ -232,16 +232,18 @@ static bool IsSpiffeId(absl::string_view uri) {
     return false;
   };
   if (uri.size() > 2048) {
-    LOG(INFO) << "Invalid SPIFFE ID: ID longer than 2048 bytes.";
+    GRPC_TRACE_LOG(tsi, INFO)
+        << "Invalid SPIFFE ID: ID longer than 2048 bytes.";
     return false;
   }
   std::vector<absl::string_view> splits = absl::StrSplit(uri, '/');
   if (splits.size() < 4 || splits[3].empty()) {
-    LOG(INFO) << "Invalid SPIFFE ID: workload id is empty.";
+    GRPC_TRACE_LOG(tsi, INFO) << "Invalid SPIFFE ID: workload id is empty.";
     return false;
   }
   if (splits[2].size() > 255) {
-    LOG(INFO) << "Invalid SPIFFE ID: domain longer than 255 characters.";
+    GRPC_TRACE_LOG(tsi, INFO)
+        << "Invalid SPIFFE ID: domain longer than 255 characters.";
     return false;
   }
   return true;
@@ -332,7 +334,7 @@ grpc_core::RefCountedPtr<grpc_auth_context> grpc_ssl_peer_to_auth_context(
                                      GRPC_PEER_SPIFFE_ID_PROPERTY_NAME,
                                      spiffe_data, spiffe_length);
     } else {
-      LOG(INFO) << "Invalid SPIFFE ID: multiple URI SANs.";
+      GRPC_TRACE_LOG(tsi, INFO) << "Invalid SPIFFE ID: multiple URI SANs.";
     }
   }
   return ctx;
@@ -419,8 +421,9 @@ grpc_security_status grpc_ssl_tsi_client_handshaker_factory_init(
   const char* root_certs;
   const tsi_ssl_root_certs_store* root_store;
   if (pem_root_certs == nullptr && !skip_server_certificate_verification) {
-    LOG(INFO) << "No root certificates specified; use ones stored in system "
-                 "default locations instead";
+    GRPC_TRACE_LOG(tsi, INFO)
+        << "No root certificates specified; use ones stored in system "
+           "default locations instead";
     // Use default root certificates.
     root_certs = grpc_core::DefaultSslRootStore::GetPemRootCerts();
     if (root_certs == nullptr) {

src/core/tsi/alts/handshaker/alts_handshaker_client.cc

@@ -220,14 +220,14 @@ void alts_handshaker_client_handle_response(alts_handshaker_client* c,
   }
   // TSI handshake has been shutdown.
   if (alts_tsi_handshaker_has_shutdown(handshaker)) {
-    LOG(INFO) << "TSI handshake shutdown";
+    VLOG(2) << "TSI handshake shutdown";
     handle_response_done(client, TSI_HANDSHAKE_SHUTDOWN,
                          "TSI handshake shutdown", nullptr, 0, nullptr);
     return;
   }
   // Check for failed grpc read.
   if (!is_ok || client->inject_read_failure) {
-    LOG(INFO) << "read failed on grpc call to handshaker service";
+    VLOG(2) << "read failed on grpc call to handshaker service";
     handle_response_done(client, TSI_INTERNAL_ERROR,
                          "read failed on grpc call to handshaker service",
                          nullptr, 0, nullptr);
@@ -470,10 +470,10 @@ static void on_status_received(void* arg, grpc_error_handle error) {
     // status from the final ALTS message with the status here.
     char* status_details =
         grpc_slice_to_c_string(client->handshake_status_details);
-    LOG(INFO) << "alts_grpc_handshaker_client:" << client
-              << " on_status_received status:" << client->handshake_status_code
-              << " details:|" << status_details << "| error:|"
-              << grpc_core::StatusToString(error) << "|";
+    VLOG(2) << "alts_grpc_handshaker_client:" << client
+            << " on_status_received status:" << client->handshake_status_code
+            << " details:|" << status_details << "| error:|"
+            << grpc_core::StatusToString(error) << "|";
     gpr_free(status_details);
   }
   maybe_complete_tsi_next(client, true /* receive_status_finished */,

src/core/tsi/alts/handshaker/alts_tsi_handshaker.cc

@@ -390,8 +390,8 @@ static void on_handshaker_service_resp_recv(void* arg,
   }
   bool success = true;
   if (!error.ok()) {
-    LOG(INFO) << "ALTS handshaker on_handshaker_service_resp_recv error: "
-              << grpc_core::StatusToString(error);
+    VLOG(2) << "ALTS handshaker on_handshaker_service_resp_recv error: "
+            << grpc_core::StatusToString(error);
     success = false;
   }
   alts_handshaker_client_handle_response(client, success);
@@ -445,7 +445,7 @@ static tsi_result alts_tsi_handshaker_continue_handshaker_next(
       CHECK_EQ(handshaker->client, nullptr);
       handshaker->client = client;
       if (handshaker->shutdown) {
-        LOG(INFO) << "TSI handshake shutdown";
+        VLOG(2) << "TSI handshake shutdown";
         if (error != nullptr) *error = "TSI handshaker shutdown";
         return TSI_HANDSHAKE_SHUTDOWN;
       }

src/core/tsi/ssl_transport_security.cc

@@ -206,7 +206,7 @@ static void init_openssl(void) {
     CRYPTO_set_locking_callback(openssl_locking_cb);
     CRYPTO_set_id_callback(openssl_thread_id_cb);
   } else {
-    LOG(INFO) << "OpenSSL callback has already been set.";
+    GRPC_TRACE_LOG(tsi, INFO) << "OpenSSL callback has already been set.";
   }
 #endif
   g_ssl_ctx_ex_factory_index =
@@ -337,7 +337,7 @@ static tsi_result peer_property_from_x509_subject(X509* cert,
                                                   bool is_verified_root_cert) {
   X509_NAME* subject_name = X509_get_subject_name(cert);
   if (subject_name == nullptr) {
-    LOG(INFO) << "Could not get subject name from certificate.";
+    GRPC_TRACE_LOG(tsi, INFO) << "Could not get subject name from certificate.";
     return TSI_NOT_FOUND;
   }
   BIO* bio = BIO_new(BIO_s_mem());
@@ -893,8 +893,9 @@ static tsi_result build_alpn_protocol_name_list(
 static int verify_cb(int ok, X509_STORE_CTX* ctx) {
   int cert_error = X509_STORE_CTX_get_error(ctx);
   if (cert_error == X509_V_ERR_UNABLE_TO_GET_CRL) {
-    LOG(INFO) << "Certificate verification failed to find relevant CRL file. "
-                 "Ignoring error.";
+    GRPC_TRACE_LOG(tsi, INFO)
+        << "Certificate verification failed to find relevant CRL file. "
+           "Ignoring error.";
     return 1;
   }
   if (cert_error != 0) {
@@ -961,7 +962,8 @@ static int RootCertExtractCallback(X509_STORE_CTX* ctx, void* /*arg*/) {
   int success =
       SSL_set_ex_data(ssl, g_ssl_ex_verified_root_cert_index, root_cert);
   if (success == 0) {
-    LOG(INFO) << "Could not set verified root cert in SSL's ex_data";
+    GRPC_TRACE_LOG(tsi, INFO)
+        << "Could not set verified root cert in SSL's ex_data";
   } else {
 #if OPENSSL_VERSION_NUMBER >= 0x10100000L
     X509_up_ref(root_cert);
@@ -979,7 +981,7 @@ static grpc_core::experimental::CrlProvider* GetCrlProvider(
   if (ssl_index < 0) {
     char err_str[256];
     ERR_error_string_n(ERR_get_error(), err_str, sizeof(err_str));
-    LOG(INFO)
+    GRPC_TRACE_LOG(tsi, INFO)
         << "error getting the SSL index from the X509_STORE_CTX while looking "
            "up Crl: "
         << err_str;
@@ -987,7 +989,8 @@ static grpc_core::experimental::CrlProvider* GetCrlProvider(
   }
   SSL* ssl = static_cast<SSL*>(X509_STORE_CTX_get_ex_data(ctx, ssl_index));
   if (ssl == nullptr) {
-    LOG(INFO) << "error while fetching from CrlProvider. SSL object is null";
+    GRPC_TRACE_LOG(tsi, INFO)
+        << "error while fetching from CrlProvider. SSL object is null";
     return nullptr;
   }
   SSL_CTX* ssl_ctx = SSL_get_SSL_CTX(ssl);
@@ -1005,13 +1008,14 @@ static absl::StatusOr<X509_CRL*> GetCrlFromProvider(
   }
   absl::StatusOr<std::string> issuer_name = grpc_core::IssuerFromCert(cert);
   if (!issuer_name.ok()) {
-    LOG(INFO) << "Could not get certificate issuer name";
+    GRPC_TRACE_LOG(tsi, INFO) << "Could not get certificate issuer name";
     return absl::InvalidArgumentError(issuer_name.status().message());
   }
   absl::StatusOr<std::string> akid = grpc_core::AkidFromCertificate(cert);
   std::string akid_to_use;
   if (!akid.ok()) {
-    LOG(INFO) << "Could not get certificate authority key identifier.";
+    GRPC_TRACE_LOG(tsi, INFO)
+        << "Could not get certificate authority key identifier.";
   } else {
     akid_to_use = *akid;
   }
@@ -1174,8 +1178,8 @@ static tsi_result tsi_set_min_and_max_tls_versions(
     SSL_CTX* ssl_context, tsi_tls_version min_tls_version,
     tsi_tls_version max_tls_version) {
   if (ssl_context == nullptr) {
-    LOG(INFO) << "Invalid nullptr argument to "
-                 "|tsi_set_min_and_max_tls_versions|.";
+    GRPC_TRACE_LOG(tsi, INFO) << "Invalid nullptr argument to "
+                                 "|tsi_set_min_and_max_tls_versions|.";
     return TSI_INVALID_ARGUMENT;
   }
 #if OPENSSL_VERSION_NUMBER >= 0x10100000
@@ -1196,7 +1200,7 @@ static tsi_result tsi_set_min_and_max_tls_versions(
       break;
 #endif
     default:
-      LOG(INFO) << "TLS version is not supported.";
+      GRPC_TRACE_LOG(tsi, INFO) << "TLS version is not supported.";
       return TSI_FAILED_PRECONDITION;
   }
 
@@ -1215,7 +1219,7 @@ static tsi_result tsi_set_min_and_max_tls_versions(
 #endif
       break;
     default:
-      LOG(INFO) << "TLS version is not supported.";
+      GRPC_TRACE_LOG(tsi, INFO) << "TLS version is not supported.";
       return TSI_FAILED_PRECONDITION;
   }
 #endif
@@ -1836,9 +1840,9 @@ static tsi_result ssl_handshaker_next(tsi_handshaker* self,
             reinterpret_cast<tsi_ssl_handshaker_result*>(*handshaker_result);
         auto cipher = SSL_get_current_cipher(result->ssl);
         if (cipher != nullptr) {
-          LOG(INFO) << absl::StrFormat("SSL Cipher Version: %s Name: %s",
-                                       SSL_CIPHER_get_version(cipher),
-                                       SSL_CIPHER_get_name(cipher));
+          GRPC_TRACE_LOG(tsi, INFO) << absl::StrFormat(
+              "SSL Cipher Version: %s Name: %s", SSL_CIPHER_get_version(cipher),
+              SSL_CIPHER_get_name(cipher));
         }
       }
     }