diff --git a/src/libstore/aws-creds.cc b/src/libstore/aws-creds.cc index 1ea37b12976..9b0ddefdca8 100644 --- a/src/libstore/aws-creds.cc +++ b/src/libstore/aws-creds.cc @@ -13,6 +13,11 @@ // C library headers for SSO provider support # include +// C library headers for custom logging +# include + +# include + # include # include @@ -30,6 +35,101 @@ AwsAuthError::AwsAuthError(int errorCode) namespace { +/** + * Map AWS log level to Nix verbosity. + * AWS levels: AWS_LL_NONE=0, AWS_LL_FATAL=1, AWS_LL_ERROR=2, AWS_LL_WARN=3, + * AWS_LL_INFO=4, AWS_LL_DEBUG=5, AWS_LL_TRACE=6 + * + * We map very conservatively because the AWS SDK is extremely noisy. What AWS + * considers "info" includes low-level details like "Initializing epoll" and + * "Starting event-loop thread". What it considers "errors" includes expected + * conditions like missing ~/.aws/config or IMDS being unavailable on non-EC2. + * + * To avoid spamming users, we only show FATAL at default verbosity. Everything + * else requires -vvvvv (lvlDebug) or higher to see. + */ +static Verbosity awsLogLevelToVerbosity(enum aws_log_level level) +{ + switch (level) { + case AWS_LL_FATAL: + return lvlError; + case AWS_LL_ERROR: + case AWS_LL_WARN: + case AWS_LL_INFO: + return lvlDebug; + case AWS_LL_DEBUG: + case AWS_LL_TRACE: + return lvlVomit; + // AWS_LL_NONE and AWS_LL_COUNT are enum sentinels, not real log levels + case AWS_LL_NONE: + case AWS_LL_COUNT: + return lvlDebug; + } + unreachable(); +} + +/** + * Custom AWS logger that routes logs through Nix's logging infrastructure. + * + * The AWS CRT C++ wrapper (ApiHandle::InitializeLogging) only supports FILE* + * or filename-based logging. The underlying C library supports custom loggers + * via aws_logger struct with a vtable containing callback functions. + */ +static int nixAwsLoggerLog( + struct aws_logger * logger, enum aws_log_level logLevel, aws_log_subject_t subject, const char * format, ...) +{ + Verbosity nixLevel = awsLogLevelToVerbosity(logLevel); + if (nixLevel > verbosity) + return AWS_OP_SUCCESS; /* Bail out early to avoid formatting the message unnecessarily. */ + + va_list args; + va_start(args, format); + std::array buffer{}; + auto res = vsnprintf(buffer.data(), buffer.size(), format, args); + va_end(args); + if (res < 0) /* Skip garbage debug messages in case the SDK is busted. */ + return AWS_OP_SUCCESS; + + const char * subjectName = aws_log_subject_name(subject); + printMsgUsing(nix::logger, nixLevel, "(aws:%s) %s", subjectName ? subjectName : "unknown", chomp(buffer.data())); + return AWS_OP_SUCCESS; +} + +/** + * Get current log level for a subject - determines which messages will be logged. + * Must be consistent with awsLogLevelToVerbosity mapping. + */ +static aws_log_level nixAwsLoggerGetLevel(struct aws_logger * logger, aws_log_subject_t subject) +{ + // Map Nix verbosity back to AWS log level (inverse of awsLogLevelToVerbosity) + if (verbosity >= lvlVomit) + return AWS_LL_TRACE; + if (verbosity >= lvlDebug) + return AWS_LL_INFO; // error/warn/info are all mapped to lvlDebug + return AWS_LL_FATAL; +} + +static void initialiseAwsLogger() +{ + static std::once_flag initialised; /* aws_logger_set must only be called once */ + std::call_once(initialised, []() { + static aws_logger_vtable nixAwsLoggerVtable = { + .log = nixAwsLoggerLog, + .get_log_level = nixAwsLoggerGetLevel, + .clean_up = [](struct aws_logger *) {}, // No resources to clean up + .set_log_level = nullptr, + }; + + static aws_logger nixAwsLogger = { + .vtable = &nixAwsLoggerVtable, + .allocator = nullptr, + .p_impl = nullptr, + }; + + aws_logger_set(&nixAwsLogger); + }); +} + /** * Helper function to wrap a C credentials provider in the C++ interface. * This replicates the static s_CreateWrappedProvider from aws-crt-cpp. @@ -119,18 +219,9 @@ class AwsCredentialProviderImpl : public AwsCredentialProvider public: AwsCredentialProviderImpl() { - // Map Nix's verbosity to AWS CRT log level - Aws::Crt::LogLevel logLevel; - if (verbosity >= lvlVomit) { - logLevel = Aws::Crt::LogLevel::Trace; - } else if (verbosity >= lvlDebug) { - logLevel = Aws::Crt::LogLevel::Debug; - } else if (verbosity >= lvlChatty) { - logLevel = Aws::Crt::LogLevel::Info; - } else { - logLevel = Aws::Crt::LogLevel::Warn; - } - apiHandle.InitializeLogging(logLevel, stderr); + // Install custom logger that routes AWS CRT logs through Nix's logging infrastructure. + // This ensures AWS logs respect Nix's verbosity settings and are formatted consistently. + initialiseAwsLogger(); // Create a shared TLS context for SSO (required for HTTPS connections) auto allocator = Aws::Crt::ApiAllocator(); diff --git a/tests/nixos/s3-binary-cache-store.nix b/tests/nixos/s3-binary-cache-store.nix index 154c1fb1b8b..5804057487d 100644 --- a/tests/nixos/s3-binary-cache-store.nix +++ b/tests/nixos/s3-binary-cache-store.nix @@ -227,7 +227,40 @@ in "Credential provider caching failed" ) - print("✓ Credential provider created once and cached") + @setup_s3() + def test_aws_log_integration(bucket): + """Test that AWS SDK logs are properly routed through Nix logger""" + print("\n=== Testing AWS Log Integration ===") + + store_url = make_s3_url(bucket) + + # With default verbosity, AWS noise should NOT appear + # All AWS messages are demoted to lvlDebug or lvlVomit + output_default = server.succeed( + f"{ENV_WITH_CREDS} nix copy --to '{store_url}' {PKGS['A']} 2>&1" + ) + + if "(aws:" in output_default: + print("Output at default verbosity:") + print(output_default) + raise Exception("Found AWS noise at default verbosity") + + # With --debug (lvlDebug), we should see AWS messages with (aws:subject) prefix + output_debug = server.succeed( + f"{ENV_WITH_CREDS} nix copy --debug --to '{store_url}' {PKGS['B']} 2>&1" + ) + + # Check for the (aws:subject) prefix format + if "(aws:" not in output_debug: + print("Output at --debug verbosity:") + print(output_debug) + raise Exception("Expected to see (aws:subject) prefix in debug output") + + # Should also see Nix's own credential provider creation message + if "creating new AWS credential provider" not in output_debug: + print("Debug output:") + print(output_debug) + raise Exception("Expected to see credential provider creation at debug level") @setup_s3(populate_bucket=[PKGS['A']]) def test_fetchurl_basic(bucket): @@ -243,8 +276,6 @@ in f"'builtins.fetchurl {{ name = \"foo\"; url = \"{cache_info_url}\"; }}'" ) - print("✓ builtins.fetchurl works with s3:// URLs") - @setup_s3() def test_error_message_formatting(bucket): """Verify error messages display URLs correctly""" @@ -263,8 +294,6 @@ in print(error_msg) raise Exception("Error message formatting failed - should show actual URL, not %s placeholder") - print("✓ Error messages format URLs correctly") - @setup_s3(populate_bucket=[PKGS['A']]) def test_fork_credential_preresolution(bucket): """Test credential pre-resolution in forked processes""" @@ -304,8 +333,6 @@ in print(output) raise Exception("Expected to find FileTransfer creation in forked process") - print(" ✓ Forked process creates fresh FileTransfer") - # Verify pre-resolution in parent required_messages = [ "Pre-resolving AWS credentials for S3 URL in builtin:fetchurl", @@ -318,8 +345,6 @@ in print(output) raise Exception(f"Missing expected message: {msg}") - print(" ✓ Parent pre-resolves credentials") - # Verify child uses pre-resolved credentials if "Using pre-resolved AWS credentials from parent process" not in output: print("Debug output:") @@ -343,8 +368,6 @@ in print(output) raise Exception(f"Child process (pid={child_pid}) should NOT create new credential providers") - print(" ✓ Child uses pre-resolved credentials (no new providers)") - @setup_s3(populate_bucket=[PKGS['A'], PKGS['B'], PKGS['C']]) def test_store_operations(bucket): """Test nix store info and copy operations""" @@ -362,8 +385,6 @@ in if not store_info.get("url"): raise Exception("Store should have a URL") - print(f" ✓ Store URL: {store_info['url']}") - # Test copy from store verify_packages_in_store(client, PKGS['A'], should_exist=False) @@ -381,9 +402,6 @@ in verify_packages_in_store(client, [PKGS['A'], PKGS['B'], PKGS['C']]) - print(" ✓ nix copy works") - print(" ✓ Credentials cached on client") - @setup_s3(populate_bucket=[PKGS['A'], PKGS['B']], public=True) def test_public_bucket_operations(bucket): """Test store operations on public bucket without credentials""" @@ -393,7 +411,6 @@ in # Verify store info works without credentials client.succeed(f"nix store info --store '{store_url}' >&2") - print(" ✓ nix store info works without credentials") # Get and validate store info JSON info_json = client.succeed(f"nix store info --json --store '{store_url}'") @@ -402,8 +419,6 @@ in if not store_info.get("url"): raise Exception("Store should have a URL") - print(f" ✓ Store URL: {store_info['url']}") - # Verify packages are not yet in client store verify_packages_in_store(client, [PKGS['A'], PKGS['B']], should_exist=False) @@ -416,8 +431,6 @@ in # Verify packages were copied successfully verify_packages_in_store(client, [PKGS['A'], PKGS['B']]) - print(" ✓ nix copy from public bucket works without credentials") - @setup_s3(populate_bucket=[PKGS['A']]) def test_url_format_variations(bucket): """Test different S3 URL parameter combinations""" @@ -426,12 +439,10 @@ in # Test parameter order variation (region before endpoint) url1 = f"s3://{bucket}?region={REGION}&endpoint={ENDPOINT}" client.succeed(f"{ENV_WITH_CREDS} nix store info --store '{url1}' >&2") - print(" ✓ Parameter order: region before endpoint works") # Test parameter order variation (endpoint before region) url2 = f"s3://{bucket}?endpoint={ENDPOINT}®ion={REGION}" client.succeed(f"{ENV_WITH_CREDS} nix store info --store '{url2}' >&2") - print(" ✓ Parameter order: endpoint before region works") @setup_s3(populate_bucket=[PKGS['A']]) def test_concurrent_fetches(bucket): @@ -485,9 +496,6 @@ in providers_created = output.count("creating new AWS credential provider") transfers_created = output.count("builtin:fetchurl creating fresh FileTransfer instance") - print(f" ✓ {providers_created} credential providers created") - print(f" ✓ {transfers_created} FileTransfer instances created") - if transfers_created != 5: print("Debug output:") print(output) @@ -513,14 +521,10 @@ in pkg_hash = get_package_hash(PKGS['B']) verify_content_encoding(server, bucket, f"{pkg_hash}.narinfo", "gzip") - print(" ✓ .narinfo has Content-Encoding: gzip") - # Verify client can download and decompress client.succeed(f"{ENV_WITH_CREDS} nix copy --from '{store_url}' --no-check-sigs {PKGS['B']}") verify_packages_in_store(client, PKGS['B']) - print(" ✓ Client decompressed .narinfo successfully") - @setup_s3() def test_compression_mixed(bucket): """Test mixed compression (narinfo=xz, ls=gzip)""" @@ -537,18 +541,14 @@ in # Verify .narinfo has xz compression verify_content_encoding(server, bucket, f"{pkg_hash}.narinfo", "xz") - print(" ✓ .narinfo has Content-Encoding: xz") # Verify .ls has gzip compression verify_content_encoding(server, bucket, f"{pkg_hash}.ls", "gzip") - print(" ✓ .ls has Content-Encoding: gzip") # Verify client can download with mixed compression client.succeed(f"{ENV_WITH_CREDS} nix copy --from '{store_url}' --no-check-sigs {PKGS['C']}") verify_packages_in_store(client, PKGS['C']) - print(" ✓ Client downloaded package with mixed compression") - @setup_s3() def test_compression_disabled(bucket): """Verify no compression by default""" @@ -560,8 +560,6 @@ in pkg_hash = get_package_hash(PKGS['A']) verify_no_compression(server, bucket, f"{pkg_hash}.narinfo") - print(" ✓ No compression applied by default") - @setup_s3() def test_nix_prefetch_url(bucket): """Test that nix-prefetch-url retrieves actual file content from S3, not empty files (issue #8862)""" @@ -581,8 +579,6 @@ in "nix hash file --type sha256 --base32 /tmp/test-file.txt" ).strip() - print(f" ✓ Uploaded test file to S3 ({test_file_size} bytes)") - # Use nix-prefetch-url to download from S3 s3_url = make_s3_url(bucket, path="/test-file.txt") @@ -602,8 +598,6 @@ in f"Hash mismatch: expected {expected_hash}, got {prefetch_hash}" ) - print(" ✓ nix-prefetch-url completed with correct hash") - # Verify the downloaded file is NOT empty (the bug in #8862) file_size = int(client.succeed(f"stat -c %s {store_path}").strip()) @@ -615,16 +609,12 @@ in f"File size mismatch: expected {test_file_size}, got {file_size}" ) - print(f" ✓ File has correct size ({file_size} bytes, not empty)") - # Verify actual content matches by comparing hashes instead of printing entire file downloaded_hash = client.succeed(f"nix hash file --type sha256 --base32 {store_path}").strip() if downloaded_hash != expected_hash: raise Exception(f"Content hash mismatch: expected {expected_hash}, got {downloaded_hash}") - print(" ✓ File content verified correct (hash matches)") - @setup_s3(populate_bucket=[PKGS['A']], versioned=True) def test_versioned_urls(bucket): """Test that versionId parameter is accepted in S3 URLs""" @@ -638,7 +628,6 @@ in f"{ENV_WITH_CREDS} nix eval --impure --expr " f"'builtins.fetchurl {{ name = \"cache-info\"; url = \"{cache_info_url}\"; }}'" ) - print(" ✓ Fetch without versionId works") # List versions to get a version ID # MinIO output format: [timestamp] size tier versionId versionNumber method filename @@ -652,8 +641,6 @@ in raise Exception("Could not extract version ID from MinIO output") version_id = version_match.group(1) - print(f" ✓ Found version ID: {version_id}") - # Version ID should not be "null" since versioning was enabled before upload if version_id == "null": raise Exception("Version ID is 'null' - versioning may not be working correctly") @@ -664,7 +651,6 @@ in f"{ENV_WITH_CREDS} nix eval --impure --expr " f"'builtins.fetchurl {{ name = \"cache-info-versioned\"; url = \"{versioned_url}\"; }}'" ) - print(" ✓ Fetch with versionId parameter works") @setup_s3() def test_multipart_upload_basic(bucket): @@ -700,13 +686,9 @@ in print(output) raise Exception(f"Expected '{expected_msg}' in output") - print(f" ✓ Multipart upload used with {expected_parts} parts") - client.succeed(f"{ENV_WITH_CREDS} nix copy --from '{store_url}' {large_pkg} --no-check-sigs") verify_packages_in_store(client, large_pkg, should_exist=True) - print(" ✓ Large file downloaded and verified") - @setup_s3() def test_multipart_threshold(bucket): """Test that files below threshold use regular upload""" @@ -729,13 +711,9 @@ in if "using S3 regular upload" not in output: raise Exception("Expected regular upload to be used") - print(" ✓ Regular upload used for file below threshold") - client.succeed(f"{ENV_WITH_CREDS} nix copy --no-check-sigs --from '{store_url}' {PKGS['A']}") verify_packages_in_store(client, PKGS['A'], should_exist=True) - print(" ✓ Small file uploaded and verified") - @setup_s3() def test_multipart_with_log_compression(bucket): """Test multipart upload with compressed build logs""" @@ -787,8 +765,6 @@ in print(output) raise Exception("Expected multipart completion message") - print(" ✓ Compressed log uploaded with multipart") - @setup_s3( populate_bucket=[PKGS['A']], profiles={ @@ -804,13 +780,11 @@ in # Verify store info works with profile credentials (no env vars) client.succeed(f"HOME=/root nix store info --store '{store_url}' >&2") - print(" ✓ nix store info works with profile credentials") # Verify we can copy from the store using profile verify_packages_in_store(client, PKGS['A'], should_exist=False) client.succeed(f"HOME=/root nix copy --no-check-sigs --from '{store_url}' {PKGS['A']}") verify_packages_in_store(client, PKGS['A']) - print(" ✓ nix copy works with profile credentials") # Clean up the package we just copied so we can test invalid profile client.succeed(f"nix store delete --ignore-liveness {PKGS['A']}") @@ -819,7 +793,6 @@ in # Verify invalid profile fails when trying to copy invalid_url = make_s3_url(bucket, profile="invalid") client.fail(f"HOME=/root nix copy --no-check-sigs --from '{invalid_url}' {PKGS['A']} 2>&1") - print(" ✓ Invalid profile credentials correctly rejected") @setup_s3( populate_bucket=[PKGS['A']], @@ -841,14 +814,12 @@ in output = client.succeed( f"HOME=/root {ENV_WITH_CREDS} nix copy --no-check-sigs --debug --from '{store_url}' {PKGS['A']} 2>&1" ) - print(" ✓ nix copy succeeded with env vars overriding wrong profile") # Verify the credential chain shows Environment provider was added if "Added AWS Environment Credential Provider" not in output: print("Debug output:") print(output) raise Exception("Expected Environment provider to be added to chain") - print(" ✓ Environment provider added to credential chain") # Clean up the package so we can test again without env vars client.succeed(f"nix store delete --ignore-liveness {PKGS['A']}") @@ -856,7 +827,6 @@ in # Without env vars, same URL should fail (proving profile creds are actually wrong) client.fail(f"HOME=/root nix copy --no-check-sigs --from '{store_url}' {PKGS['A']} 2>&1") - print(" ✓ Without env vars, wrong profile credentials correctly fail") @setup_s3( populate_bucket=[PKGS['A']], @@ -882,14 +852,12 @@ in print("Debug output:") print(output) raise Exception(f"Expected to find: {msg}") - print(f" ✓ {provider} provider added to chain") # SSO should be skipped (no SSO config for this profile) if "Skipped AWS SSO Credential Provider for profile 'testprofile'" not in output: print("Debug output:") print(output) raise Exception("Expected SSO provider to be skipped") - print(" ✓ SSO provider correctly skipped (not configured)") # ============================================================================ # Main Test Execution @@ -909,6 +877,7 @@ in # Run tests (each gets isolated bucket via decorator) test_credential_caching() + test_aws_log_integration() test_fetchurl_basic() test_error_message_formatting() test_fork_credential_preresolution() @@ -927,9 +896,5 @@ in test_profile_credentials() test_env_vars_precedence() test_credential_provider_chain() - - print("\n" + "="*80) - print("✓ All S3 Binary Cache Store Tests Passed!") - print("="*80) ''; }