From b807624b9ffc985178aeecaec24b0df4033b8b72 Mon Sep 17 00:00:00 2001 From: Yash Tibrewal Date: Tue, 23 Jul 2024 23:54:14 -0700 Subject: [PATCH] [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 ea1c7718dabeb813af7cf96224690a14037f6b32 PiperOrigin-RevId: 655450344 --- .../credentials/alts/check_gcp_environment.cc | 2 +- .../alts/check_gcp_environment_no_op.cc | 2 +- .../security/credentials/jwt/json_token.cc | 2 +- .../credentials/jwt/jwt_credentials.cc | 17 +++++---- .../tls/grpc_tls_certificate_provider.cc | 6 ++-- .../tls/grpc_tls_credentials_options.cc | 5 ++- .../credentials/tls/tls_credentials.cc | 4 +-- .../security/security_connector/ssl_utils.cc | 15 ++++---- .../alts/handshaker/alts_handshaker_client.cc | 12 +++---- .../alts/handshaker/alts_tsi_handshaker.cc | 6 ++-- src/core/tsi/ssl_transport_security.cc | 36 ++++++++++--------- 11 files changed, 56 insertions(+), 51 deletions(-) diff --git a/src/core/lib/security/credentials/alts/check_gcp_environment.cc b/src/core/lib/security/credentials/alts/check_gcp_environment.cc index ff7ce1e33bf..50406fb8a54 100644 --- a/src/core/lib/security/credentials/alts/check_gcp_environment.cc +++ b/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]; diff --git a/src/core/lib/security/credentials/alts/check_gcp_environment_no_op.cc b/src/core/lib/security/credentials/alts/check_gcp_environment_no_op.cc index 9174d301799..d9078a4c81a 100644 --- a/src/core/lib/security/credentials/alts/check_gcp_environment_no_op.cc +++ b/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; } diff --git a/src/core/lib/security/credentials/jwt/json_token.cc b/src/core/lib/security/credentials/jwt/json_token.cc index 0c81efb6690..64c0f425985 100644 --- a/src/core/lib/security/credentials/jwt/json_token.cc +++ b/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()); } diff --git a/src/core/lib/security/credentials/jwt/jwt_credentials.cc b/src/core/lib/security/credentials/jwt/jwt_credentials.cc index 1461b516e23..33636819c4f 100644 --- a/src/core/lib/security/credentials/jwt/jwt_credentials.cc +++ b/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); diff --git a/src/core/lib/security/credentials/tls/grpc_tls_certificate_provider.cc b/src/core/lib/security/credentials/tls/grpc_tls_certificate_provider.cc index 8b85e3d946f..82a56f43ebc 100644 --- a/src/core/lib/security/credentials/tls/grpc_tls_certificate_provider.cc +++ b/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()) { 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. diff --git a/src/core/lib/security/credentials/tls/grpc_tls_credentials_options.cc b/src/core/lib/security/credentials/tls/grpc_tls_credentials_options.cc index 843a408cb94..82a6dd55620 100644 --- a/src/core/lib/security/credentials/tls/grpc_tls_credentials_options.cc +++ b/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 : ""); } diff --git a/src/core/lib/security/credentials/tls/tls_credentials.cc b/src/core/lib/security/credentials/tls/tls_credentials.cc index d825b365cb7..765f669e5ce 100644 --- a/src/core/lib/security/credentials/tls/tls_credentials.cc +++ b/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()); } diff --git a/src/core/lib/security/security_connector/ssl_utils.cc b/src/core/lib/security/security_connector/ssl_utils.cc index 840602eec4e..a251ccdf86c 100644 --- a/src/core/lib/security/security_connector/ssl_utils.cc +++ b/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 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_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) { diff --git a/src/core/tsi/alts/handshaker/alts_handshaker_client.cc b/src/core/tsi/alts/handshaker/alts_handshaker_client.cc index 871b3515dc2..5f402f8c8eb 100644 --- a/src/core/tsi/alts/handshaker/alts_handshaker_client.cc +++ b/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 */, diff --git a/src/core/tsi/alts/handshaker/alts_tsi_handshaker.cc b/src/core/tsi/alts/handshaker/alts_tsi_handshaker.cc index ef91dec2087..16d86e27856 100644 --- a/src/core/tsi/alts/handshaker/alts_tsi_handshaker.cc +++ b/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; } diff --git a/src/core/tsi/ssl_transport_security.cc b/src/core/tsi/ssl_transport_security.cc index 23067f32bda..3149eb283fe 100644 --- a/src/core/tsi/ssl_transport_security.cc +++ b/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(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 GetCrlFromProvider( } absl::StatusOr 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 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(*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)); } } }