niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #395
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica8=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica9=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun10=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun11=== RUN TestCaseHackSuffix12=== PAUSE TestCaseHackSuffix13=== RUN TestFilterOversizedClosures14=== PAUSE TestFilterOversizedClosures15=== RUN TestUploadMultipart_PartsInParallel16=== PAUSE TestUploadMultipart_PartsInParallel17=== RUN TestPartSizeForNAR18=== PAUSE TestPartSizeForNAR19=== RUN TestUploadMultipart_SupersededByPeer20=== PAUSE TestUploadMultipart_SupersededByPeer21=== RUN TestDumpPathCaseHackMatchesNix22--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)23=== RUN TestDumpPathCaseHackCollision24--- PASS: TestDumpPathCaseHackCollision (0.00s)25=== RUN TestDumpPathMatchesNix26=== PAUSE TestDumpPathMatchesNix27=== RUN TestDumpPathSingleFile28=== PAUSE TestDumpPathSingleFile29=== RUN TestDumpPathWriterError30=== PAUSE TestDumpPathWriterError31=== RUN TestEncodeNixBase3232=== PAUSE TestEncodeNixBase3233=== RUN TestEncodeNixBase32WithRealHash34=== PAUSE TestEncodeNixBase32WithRealHash35=== RUN TestConvertHashToNix3236=== PAUSE TestConvertHashToNix3237=== RUN TestGetStorePathHash38=== PAUSE TestGetStorePathHash39=== RUN TestPathInfoHashCompatibility40=== PAUSE TestPathInfoHashCompatibility41=== RUN TestParsePathInfoJSON42=== PAUSE TestParsePathInfoJSON43=== RUN TestParsePathInfoJSONMultiplePaths44=== PAUSE TestParsePathInfoJSONMultiplePaths45=== RUN TestPathInfoCACompatibility46=== PAUSE TestPathInfoCACompatibility47=== RUN TestRateLimiterFeedback48=== PAUSE TestRateLimiterFeedback49=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess50=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess51=== RUN TestResolveStorePath52=== PAUSE TestResolveStorePath53=== RUN TestDoWithRetry_BodyReplayedViaGetBody54=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody55=== RUN TestShellSplit56=== PAUSE TestShellSplit57=== RUN TestShellSplitErrors58=== PAUSE TestShellSplitErrors59=== RUN TestStreamPushReportsEveryPath60=== PAUSE TestStreamPushReportsEveryPath61=== RUN TestStreamPushBatchesUnderLoad62=== PAUSE TestStreamPushBatchesUnderLoad63=== RUN TestStreamPushIsolatesFailures64=== PAUSE TestStreamPushIsolatesFailures65=== RUN TestStreamPushGivesUpOnDeadServer66=== PAUSE TestStreamPushGivesUpOnDeadServer67=== RUN TestStreamPushRequestLine68=== PAUSE TestStreamPushRequestLine69=== RUN TestStreamPushReportsSignatures70=== PAUSE TestStreamPushReportsSignatures71=== RUN TestClientSignaturesByStorePath72=== PAUSE TestClientSignaturesByStorePath73=== RUN TestSetClientTLS74=== PAUSE TestSetClientTLS75=== RUN TestSetClientTLSDoesNotMutateDefaultTransport76=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport77=== RUN TestSetClientTLSErrors78=== PAUSE TestSetClientTLSErrors79=== RUN TestStaticToken80=== PAUSE TestStaticToken81=== RUN TestFileTokenReadsAndCaches82=== PAUSE TestFileTokenReadsAndCaches83=== RUN TestFileTokenMissing84=== PAUSE TestFileTokenMissing85=== RUN TestFileTokenEmpty86=== PAUSE TestFileTokenEmpty87=== RUN TestScriptTokenNoExpiryRerunsEveryCall88=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall89=== RUN TestScriptTokenCachesUntilRefresh90=== PAUSE TestScriptTokenCachesUntilRefresh91=== RUN TestScriptTokenEmptyToken92=== PAUSE TestScriptTokenEmptyToken93=== RUN TestScriptTokenBadJSON94=== PAUSE TestScriptTokenBadJSON95=== RUN TestScriptTokenScriptFails96=== PAUSE TestScriptTokenScriptFails97=== RUN TestScriptTokenEmptyCommand98=== PAUSE TestScriptTokenEmptyCommand99=== CONT TestDoServerRequestAttachesToken100=== CONT TestSetClientTLSErrors101=== CONT TestDoWithRetry_BodyReplayedViaGetBody102=== CONT TestSetClientTLSDoesNotMutateDefaultTransport103=== CONT TestSetClientTLS104=== CONT TestClientSignaturesByStorePath105--- PASS: TestClientSignaturesByStorePath (0.00s)106=== CONT TestPathInfoHashCompatibility107=== CONT TestStreamPushReportsSignatures108=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)109=== CONT TestStreamPushRequestLine110=== CONT TestStreamPushGivesUpOnDeadServer111=== CONT TestStreamPushIsolatesFailures112=== CONT TestStreamPushBatchesUnderLoad1132026/10/07 07:42:47 ERROR Upload failed error="bad path" count=3114=== CONT TestStreamPushReportsEveryPath1152026/10/07 07:42:47 ERROR Upload failed error="connection refused" count=201162026/10/07 07:42:47 ERROR Server seems unavailable, giving up on batch untried=171172026/10/07 07:42:47 ERROR Upload failed error=boom count=1118--- PASS: TestStreamPushReportsSignatures (0.00s)1192026/10/07 07:42:47 ERROR Upload failed error=boom count=1120=== CONT TestShellSplitErrors121=== CONT TestConvertHashToNix32122=== RUN TestConvertHashToNix32/SRI_format_to_Nix32123=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32124=== RUN TestConvertHashToNix32/already_Nix32_format125=== PAUSE TestConvertHashToNix32/already_Nix32_format126=== RUN TestConvertHashToNix32/invalid_format127=== CONT TestEncodeNixBase32WithRealHash128=== CONT TestFileTokenReadsAndCaches129=== CONT TestScriptTokenScriptFails130=== CONT TestScriptTokenEmptyCommand131=== CONT TestEncodeNixBase32132=== CONT TestResolveStorePath133=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1342026/10/07 07:42:47 WARN Rate limiter enabled after throttle name=server-test rate=5135=== CONT TestRateLimiterFeedback1362026/10/07 07:42:47 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:46071137=== RUN TestRateLimiterFeedback/429_enables_limiter138=== CONT TestPathInfoCACompatibility139=== CONT TestParsePathInfoJSONMultiplePaths140=== CONT TestScriptTokenCachesUntilRefresh141=== CONT TestParsePathInfoJSON142=== PAUSE TestRateLimiterFeedback/429_enables_limiter143=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)144=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths145=== CONT TestDumpPathWriterError146=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon1472026/10/07 07:42:47 WARN Rate limiter enabled after throttle name=server-test rate=5148=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1492026/10/07 07:42:47 WARN Rate limiter backed off name=server-test rate=51502026/10/07 07:42:47 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:46071151=== CONT TestScriptTokenBadJSON152=== CONT TestScriptTokenEmptyToken153=== CONT TestShellSplit154=== PAUSE TestConvertHashToNix32/invalid_format155=== CONT TestUploadMultipart_PartsInParallel156=== RUN TestEncodeNixBase32/test_string_hash157=== RUN TestSetClientTLSErrors/missing_cert_file158=== RUN TestPathInfoCACompatibility/null_ca_field159--- PASS: TestStreamPushIsolatesFailures (0.00s)160=== RUN TestParsePathInfoJSON/Nix_format161=== CONT TestGetStorePathHash162=== RUN TestRateLimiterFeedback/503_enables_limiter163=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths164=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun165=== PAUSE TestRateLimiterFeedback/503_enables_limiter166=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter167=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter168=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter169=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter170=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths171=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon172=== CONT TestFileTokenMissing173=== CONT TestDumpPathSingleFile174=== CONT TestPartSizeForNAR175=== CONT TestFilterOversizedClosures176=== CONT TestDumpPathMatchesNix177=== PAUSE TestEncodeNixBase32/test_string_hash178--- PASS: TestStreamPushReportsEveryPath (0.00s)179--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)180--- PASS: TestShellSplitErrors (0.00s)181--- PASS: TestEncodeNixBase32WithRealHash (0.00s)182=== PAUSE TestPathInfoCACompatibility/null_ca_field183=== PAUSE TestParsePathInfoJSON/Nix_format184=== CONT TestCaseHackSuffix185=== CONT TestScriptTokenNoExpiryRerunsEveryCall186=== RUN TestParsePathInfoJSON/Lix_format187=== PAUSE TestParsePathInfoJSON/Lix_format188=== CONT TestStaticToken1892026/10/07 07:42:47 INFO Garbage collection started190=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica191=== RUN TestSetClientTLS/rejects_connection_without_client_cert192=== CONT TestUploadMultipart_SupersededByPeer193=== PAUSE TestSetClientTLSErrors/missing_cert_file194=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI195=== RUN TestGetStorePathHash/valid_store_path196=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI197=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512198=== RUN TestPartSizeForNAR/zero_stays_at_minimum199=== RUN TestEncodeNixBase32/empty_input200=== RUN TestFilterOversizedClosures/no_limit_keeps_everything201=== RUN TestPathInfoCACompatibility/old_string_format_-_text202=== CONT TestFileTokenEmpty203=== RUN TestParsePathInfoJSON/empty_input204=== PAUSE TestParsePathInfoJSON/empty_input205=== RUN TestParsePathInfoJSON/whitespace_only206=== PAUSE TestParsePathInfoJSON/whitespace_only207=== CONT TestRegisterUploadedObjectReusesConnections208=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert209=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA210=== RUN TestUploadMultipart_SupersededByPeer/exists211=== PAUSE TestUploadMultipart_SupersededByPeer/exists212=== RUN TestUploadMultipart_SupersededByPeer/missing213=== PAUSE TestGetStorePathHash/valid_store_path214=== RUN TestGetStorePathHash/basename_without_hyphen_should_error215--- PASS: TestScriptTokenEmptyCommand (0.00s)216=== RUN TestSetClientTLSErrors/missing_key_file217=== PAUSE TestSetClientTLSErrors/missing_key_file218=== RUN TestSetClientTLSErrors/missing_ca_file219=== PAUSE TestSetClientTLSErrors/missing_ca_file220--- PASS: TestDoServerRequestAttachesToken (0.01s)221=== PAUSE TestEncodeNixBase32/empty_input222--- PASS: TestFileTokenReadsAndCaches (0.00s)223--- PASS: TestScriptTokenScriptFails (0.00s)224--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)225--- PASS: TestResolveStorePath (0.00s)226--- PASS: TestShellSplit (0.00s)227--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)228--- PASS: TestFileTokenMissing (0.00s)229--- PASS: TestScriptTokenEmptyToken (0.00s)230--- PASS: TestStaticToken (0.00s)231--- PASS: TestScriptTokenBadJSON (0.08s)232--- PASS: TestFileTokenEmpty (0.00s)233=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text234=== CONT TestConvertHashToNix32/invalid_format235=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive236=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2372026/10/07 07:42:47 INFO Garbage collection started238=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything239--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.08s)240=== CONT TestRateLimiterFeedback/429_enables_limiter241=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped242=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped243=== RUN TestFilterOversizedClosures/all_closures_skipped244=== PAUSE TestFilterOversizedClosures/all_closures_skipped245=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA246=== RUN TestSetClientTLS/preserves_debug_logging_transport247=== PAUSE TestSetClientTLS/preserves_debug_logging_transport248=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter249=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error250=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error251=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error2522026/10/07 07:42:47 WARN Rate limiter enabled after throttle name=server-test rate=5253=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error2542026/10/07 07:42:47 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:40855255=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error2562026/10/07 07:42:47 INFO Garbage collection progress phase=running_on_another_replica failed_uploads_deleted=0 old_closures_deleted=0 objects_marked=0 objects_deleted=0 objects_failed=0257=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512258=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter259=== RUN TestSetClientTLSErrors/invalid_ca_file260=== PAUSE TestSetClientTLSErrors/invalid_ca_file261=== CONT TestRateLimiterFeedback/503_enables_limiter2622026/10/07 07:42:47 WARN Rate limiter backed off name=server-test rate=5263=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths264=== CONT TestConvertHashToNix32/SRI_format_to_Nix32265=== CONT TestEncodeNixBase32/test_string_hash266=== CONT TestFilterOversizedClosures/no_limit_keeps_everything267=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum268=== RUN TestPartSizeForNAR/small_stays_at_minimum269=== PAUSE TestPartSizeForNAR/small_stays_at_minimum270=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum271=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum272=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts273=== CONT TestFilterOversizedClosures/all_closures_skipped2742026/10/07 07:42:47 WARN Rate limiter enabled after throttle name=server-test rate=52752026/10/07 07:42:47 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50276=== CONT TestSetClientTLS/preserves_debug_logging_transport2772026/10/07 07:42:47 WARN Garbage collection finished on another replica. Its statistics are not available here278=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA2792026/10/07 07:42:47 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:44005280--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)281=== CONT TestGetStorePathHash/valid_store_path282=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)283=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error284=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error285=== CONT TestGetStorePathHash/basename_without_hyphen_should_error286--- PASS: TestGetStorePathHash (0.08s)287 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)288 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)289 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)290 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)291=== CONT TestSetClientTLSErrors/missing_cert_file292=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512293=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI294=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon2952026/10/07 07:42:47 WARN Rate limiter backed off name=server-test rate=5296--- PASS: TestPathInfoHashCompatibility (0.09s)297 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)298 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)299 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)300 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)301=== CONT TestSetClientTLSErrors/invalid_ca_file302=== CONT TestSetClientTLSErrors/missing_ca_file303--- PASS: TestRateLimiterFeedback (0.00s)304 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)305 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)306 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)307 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)308=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts309=== RUN TestPathInfoCACompatibility/new_structured_format_-_text310=== RUN TestParsePathInfoJSON/invalid_JSON311=== PAUSE TestUploadMultipart_SupersededByPeer/missing312=== CONT TestSetClientTLSErrors/missing_key_file313=== PAUSE TestParsePathInfoJSON/invalid_JSON314=== CONT TestUploadMultipart_SupersededByPeer/missing315=== RUN TestPartSizeForNAR/1_TiB316=== PAUSE TestPartSizeForNAR/1_TiB317=== RUN TestPartSizeForNAR/5_TiB_S3_max_object318=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object319=== RUN TestPartSizeForNAR/capped_at_5_GiB320=== PAUSE TestPartSizeForNAR/capped_at_5_GiB321=== CONT TestParsePathInfoJSON/Nix_format322=== CONT TestParsePathInfoJSON/empty_input323=== CONT TestPartSizeForNAR/zero_stays_at_minimum324=== CONT TestPartSizeForNAR/capped_at_5_GiB325=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts326=== CONT TestPartSizeForNAR/1_TiB327=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum328=== CONT TestPartSizeForNAR/small_stays_at_minimum329--- PASS: TestScriptTokenCachesUntilRefresh (0.09s)330--- PASS: TestSetClientTLSErrors (0.09s)331 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)332 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)333 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)334 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)335=== CONT TestParsePathInfoJSON/Lix_format336=== CONT TestPartSizeForNAR/5_TiB_S3_max_object337=== CONT TestConvertHashToNix32/already_Nix32_format338--- PASS: TestConvertHashToNix32 (0.00s)339 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)340 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)341 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)342=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3432026/10/07 07:42:47 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000344--- PASS: TestFilterOversizedClosures (0.08s)345 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)346 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)347 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)348=== CONT TestUploadMultipart_SupersededByPeer/exists349--- PASS: TestPartSizeForNAR (0.09s)350 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)351 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)352 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)353 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)354 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)355 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)356 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)357=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths358--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)359 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)360 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)361=== CONT TestParsePathInfoJSON/whitespace_only362=== CONT TestSetClientTLS/rejects_connection_without_client_cert363=== CONT TestParsePathInfoJSON/invalid_JSON364--- PASS: TestParsePathInfoJSON (0.09s)365 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)366 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)367 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)368 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)369 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)370=== CONT TestEncodeNixBase32/empty_input371--- PASS: TestEncodeNixBase32 (0.08s)372 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)373 --- PASS: TestEncodeNixBase32/empty_input (0.00s)374=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text375--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)376=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method377=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method378=== CONT TestPathInfoCACompatibility/null_ca_field379=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method380=== CONT TestPathInfoCACompatibility/new_structured_format_-_text381=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive382=== CONT TestPathInfoCACompatibility/old_string_format_-_text383--- PASS: TestPathInfoCACompatibility (0.10s)384 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)385 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)386 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)387 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)388 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)389--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)390 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)391 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)392--- PASS: TestStreamPushRequestLine (0.11s)3932026/10/07 07:42:47 http: TLS handshake error from 127.0.0.1:59722: remote error: tls: bad certificate394--- PASS: TestSetClientTLS (0.09s)395 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)396 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.02s)397 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)398--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)399--- PASS: TestDumpPathSingleFile (0.12s)400--- PASS: TestCaseHackSuffix (0.04s)401--- PASS: TestStreamPushBatchesUnderLoad (0.14s)402--- PASS: TestDumpPathWriterError (0.14s)403--- PASS: TestDumpPathMatchesNix (0.17s)404--- PASS: TestUploadMultipart_PartsInParallel (0.70s)405--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)406PASS407Running server tests...408The files belonging to this database system will be owned by user "nixbld".409This user must also own the server process.410411The database cluster will be initialized with locale "C".412The default database encoding has accordingly been set to "SQL_ASCII".413The default text search configuration will be set to "english".414415Data page checksums are enabled.416417creating directory /build/postgres439672649/data ... ok418creating subdirectories ... ok419selecting dynamic shared memory implementation ... posix420selecting default "max_connections" ... 100421selecting default "shared_buffers" ... 128MB422selecting default time zone ... UTC423creating configuration files ... ok424running bootstrap script ... ok425performing post-bootstrap initialization ... ok426syncing data to disk ... ok427428initdb: warning: enabling "trust" authentication for local connections429initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.430431Success. You can now start the database server using:432433 pg_ctl -D /build/postgres439672649/data -l logfile start434435/build/postgres439672649:5432 - no response4362026-10-07 07:42:48.979 UTC [128] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4372026-10-07 07:42:48.980 UTC [128] LOG: listening on Unix socket "/build/postgres439672649/.s.PGSQL.5432"4382026-10-07 07:42:48.985 UTC [135] LOG: database system was shut down at 2026-10-07 07:42:48 UTC4392026-10-07 07:42:48.989 UTC [128] LOG: database system is ready to accept connections440/build/postgres439672649:5432 - accepting connections441{"timestamp":"2026-10-07T07:42:49.28349532Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"8ef4b8c1-1367-4108-8534-29b639371045","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(389)"}442=== RUN TestService_AuthMiddleware443=== PAUSE TestService_AuthMiddleware444=== RUN TestService_AuthMiddleware_MTLSProxyHeader445=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader446=== RUN TestService_AuthMiddleware_MTLSBoundSubjects447=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects448=== RUN TestService_ReadAuthMiddleware449=== PAUSE TestService_ReadAuthMiddleware450=== RUN TestService_AuthMiddleware_OIDC451=== PAUSE TestService_AuthMiddleware_OIDC452=== RUN TestService_RequireScope_OIDC453=== PAUSE TestService_RequireScope_OIDC454=== RUN TestService_ReadScope_PublicByDefault455=== PAUSE TestService_ReadScope_PublicByDefault456=== RUN TestCacheConfigHandler457=== PAUSE TestCacheConfigHandler458=== RUN TestCacheStatsHandler459=== PAUSE TestCacheStatsHandler460=== RUN TestClientCADerivations461=== PAUSE TestClientCADerivations462=== RUN TestClientErrorHandling463=== PAUSE TestClientErrorHandling464=== RUN TestClientIntegration465=== PAUSE TestClientIntegration466=== RUN TestClientMultipleUploads467=== PAUSE TestClientMultipleUploads468=== RUN TestClientWithDependencies469=== PAUSE TestClientWithDependencies470=== RUN TestClientSharedPathCommittedMidPush471=== PAUSE TestClientSharedPathCommittedMidPush472=== RUN TestPinProtectsFromGC473=== PAUSE TestPinProtectsFromGC474=== RUN TestClientPushesUseOnePush475=== PAUSE TestClientPushesUseOnePush476=== RUN TestClientFallsBackToClosures477=== PAUSE TestClientFallsBackToClosures478=== RUN TestDeleteClosuresRacingPins479=== PAUSE TestDeleteClosuresRacingPins480=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock481=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock482=== RUN TestResolveDBConnectionString483=== PAUSE TestResolveDBConnectionString484=== RUN TestConnectWaitsForAPeerMigration485=== PAUSE TestConnectWaitsForAPeerMigration486=== RUN TestLeadElectsOneAndHandsOver487=== PAUSE TestLeadElectsOneAndHandsOver488=== RUN TestLeadIncumbentWinsAfterRestart4892026/10/07 07:42:49 INFO lead: acquired remote=192.0.2.1:12344902026/10/07 07:42:50 INFO lead: released remote=192.0.2.1:12344912026/10/07 07:42:50 INFO lead: acquired remote=192.0.2.1:12344922026/10/07 07:42:51 INFO lead: released remote=192.0.2.1:1234493--- PASS: TestLeadIncumbentWinsAfterRestart (1.88s)494=== RUN TestLeadIncumbentAnnouncesAtOnce495=== PAUSE TestLeadIncumbentAnnouncesAtOnce496=== RUN TestLeadEndsOnShutdown497=== PAUSE TestLeadEndsOnShutdown498=== RUN TestLeadEndsWhenItsConnectionHangs4992026/10/07 07:42:51 INFO lead: acquired remote=192.0.2.1:12345002026-10-07 07:42:52.782 UTC [573] FATAL: terminating connection due to administrator command5012026/10/07 07:42:52 INFO lead: acquired remote=192.0.2.1:12345022026/10/07 07:42:53 WARN lead: lock connection lost error="timeout: context deadline exceeded"5032026/10/07 07:42:53 INFO lead: released remote=192.0.2.1:12345042026/10/07 07:42:54 INFO lead: released remote=192.0.2.1:1234505--- PASS: TestLeadEndsWhenItsConnectionHangs (2.91s)506=== RUN TestGCAdvisoryLockBlocksConcurrentRun507=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun508=== RUN TestGCBugBareHashReferences509=== PAUSE TestGCBugBareHashReferences510=== RUN TestGCMetrics511=== PAUSE TestGCMetrics512=== RUN TestPushDedupSurvivesConcurrentGC513=== PAUSE TestPushDedupSurvivesConcurrentGC514=== RUN TestDeduplicatedObjectsRecordedAsPending515=== PAUSE TestDeduplicatedObjectsRecordedAsPending516=== RUN TestGCSweepSkipsPendingObjects517=== PAUSE TestGCSweepSkipsPendingObjects518=== RUN TestTombstonedObjectOfferedWithoutWaiting519=== PAUSE TestTombstonedObjectOfferedWithoutWaiting520=== RUN TestGCSweepDeliversEachKeyOnce521=== PAUSE TestGCSweepDeliversEachKeyOnce522=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection523=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection524=== RUN TestForceGCDuringPushOffersSweptObject525=== PAUSE TestForceGCDuringPushOffersSweptObject526=== RUN TestFailedS3DeleteKeepsTombstone527=== PAUSE TestFailedS3DeleteKeepsTombstone528=== RUN TestSweepSkipsRowsLockedByPush529=== PAUSE TestSweepSkipsRowsLockedByPush530=== RUN TestRegisterCompletedObjectNeedsPendingRow531=== PAUSE TestRegisterCompletedObjectNeedsPendingRow532=== RUN TestGetExistingObjectsLocksRows533=== PAUSE TestGetExistingObjectsLocksRows534=== RUN TestSweepRechecksPendingAfterLocking535=== PAUSE TestSweepRechecksPendingAfterLocking536=== RUN TestPushWaitsForSweepHoldingRow537=== PAUSE TestPushWaitsForSweepHoldingRow538=== RUN TestCommitRacingPendingCleanupKeepsObjects539=== PAUSE TestCommitRacingPendingCleanupKeepsObjects540=== RUN TestGCEndsOnShutdown541=== PAUSE TestGCEndsOnShutdown542=== RUN TestGCTaskStore_StartNew543=== PAUSE TestGCTaskStore_StartNew544=== RUN TestGCTaskStore_DeduplicateSameParams545=== PAUSE TestGCTaskStore_DeduplicateSameParams546=== RUN TestGCTaskStore_ConflictDifferentParams547=== PAUSE TestGCTaskStore_ConflictDifferentParams548=== RUN TestGCTaskStore_GetEmpty549=== PAUSE TestGCTaskStore_GetEmpty550=== RUN TestGCTaskStore_GetReturnsLatest551=== PAUSE TestGCTaskStore_GetReturnsLatest552=== RUN TestGCTaskStore_CompletedAllowsNewTask553=== PAUSE TestGCTaskStore_CompletedAllowsNewTask554=== RUN TestGCTaskStore_PhaseUpdates555=== PAUSE TestGCTaskStore_PhaseUpdates556=== RUN TestGCTaskStore_Fail557=== PAUSE TestGCTaskStore_Fail558=== RUN TestGracefulShutdownDrainsInflight559=== PAUSE TestGracefulShutdownDrainsInflight560=== RUN TestService_healthCheckHandler561=== PAUSE TestService_healthCheckHandler562=== RUN TestService_readinessHandler563=== PAUSE TestService_readinessHandler564=== RUN TestGenerateLandingPage565=== PAUSE TestGenerateLandingPage566=== RUN TestCacheConfigHandlerMaxNarSize567=== PAUSE TestCacheConfigHandlerMaxNarSize568=== RUN TestCreatePendingClosureRejectsOversizedNAR569=== PAUSE TestCreatePendingClosureRejectsOversizedNAR570=== RUN TestNARDeduplicationMetadataUploadBug571=== PAUSE TestNARDeduplicationMetadataUploadBug572=== RUN TestMetricsInventory573=== PAUSE TestMetricsInventory574=== RUN TestMetricsCommit575=== PAUSE TestMetricsCommit576=== RUN TestService_NativeMTLS577=== PAUSE TestService_NativeMTLS578=== RUN TestServerTLSConfig579=== PAUSE TestServerTLSConfig580=== RUN TestMultipartCleanup581=== PAUSE TestMultipartCleanup582=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded583=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded584=== RUN TestPendingCleanupUsesOneCutoff585=== PAUSE TestPendingCleanupUsesOneCutoff586=== RUN TestObjectStatsTrigger587=== PAUSE TestObjectStatsTrigger588=== RUN TestObjectStatsLargeCommit589=== PAUSE TestObjectStatsLargeCommit590=== RUN TestOrphanedObjectsGC591=== PAUSE TestOrphanedObjectsGC592=== RUN TestOrphanedObjectsGCStressTest593=== PAUSE TestOrphanedObjectsGCStressTest594=== RUN TestCreatePin_ReservedPins595=== PAUSE TestCreatePin_ReservedPins596=== RUN TestPresentReportsOnlyClosureRoots597=== PAUSE TestPresentReportsOnlyClosureRoots598=== RUN TestPresentRefreshesOnlyStaleClosures599=== PAUSE TestPresentRefreshesOnlyStaleClosures600=== RUN TestPresentNotReportedWhileGCDeletesClosure601=== PAUSE TestPresentNotReportedWhileGCDeletesClosure602=== RUN TestParseSingleRange603=== PAUSE TestParseSingleRange604=== RUN TestProxyHeadersOnlyTrustedOnSocket6052026/10/07 07:42:54 INFO Starting HTTP server address=127.0.0.1:368576062026/10/07 07:42:54 INFO Starting HTTP server address=proxy.sock6072026/10/07 07:42:54 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6082026/10/07 07:42:54 INFO Shutdown signal received, draining in-flight requests timeout=10s609--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.11s)610=== RUN TestIsValidCachePath611=== PAUSE TestIsValidCachePath612=== RUN TestReadProxyNarinfo613=== PAUSE TestReadProxyNarinfo614=== RUN TestReadProxyNarinfoAlreadyDecompressed615=== PAUSE TestReadProxyNarinfoAlreadyDecompressed616=== RUN TestReadProxyContentNegotiation617=== PAUSE TestReadProxyContentNegotiation618=== RUN TestReadProxyNarStreaming619=== PAUSE TestReadProxyNarStreaming620=== RUN TestReadProxy404621=== PAUSE TestReadProxy404622=== RUN TestReadProxyInvalidPath623=== PAUSE TestReadProxyInvalidPath624=== RUN TestReadProxyHead625=== PAUSE TestReadProxyHead626=== RUN TestReadProxyOutlastsServerWriteTimeout627=== PAUSE TestReadProxyOutlastsServerWriteTimeout628=== RUN TestReadProxyConditionalGet629=== PAUSE TestReadProxyConditionalGet630=== RUN TestReadProxyRootRedirectsToIndexHTML631=== PAUSE TestReadProxyRootRedirectsToIndexHTML632=== RUN TestReadProxyDisabled633=== PAUSE TestReadProxyDisabled634=== RUN TestReadRedirectNar635=== PAUSE TestReadRedirectNar636=== RUN TestReadRedirectKeepsNarinfoProxied637=== PAUSE TestReadRedirectKeepsNarinfoProxied638=== RUN TestReadProxyRangeRequest639=== PAUSE TestReadProxyRangeRequest640=== RUN TestReadRedirectUsesPublicS3URL641=== PAUSE TestReadRedirectUsesPublicS3URL642=== RUN TestPush_OverlappingRootsStoreOneRowPerKey643=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey644=== RUN TestPush_CompleteCommitsEveryRoot645=== PAUSE TestPush_CompleteCommitsEveryRoot646=== RUN TestPush_RepeatedRootCommitsOnce647=== PAUSE TestPush_RepeatedRootCommitsOnce648=== RUN TestPush_CompleteWaitsForCleanupOfThePush649=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush650=== RUN TestPush_RootsAreLockedInByteOrder651=== PAUSE TestPush_RootsAreLockedInByteOrder652=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit653=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit654=== RUN TestPush_RejectsBadRequests655=== PAUSE TestPush_RejectsBadRequests656=== RUN TestPush_SignsNarinfosOfItsPendingObjects657=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects658=== RUN TestRedundantMultipartUpload659=== PAUSE TestRedundantMultipartUpload660=== RUN TestCompleteMultipartUpload_ErrorButObjectExists661=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists662=== RUN TestCompletedNarNotReofferedAcrossClosures663=== PAUSE TestCompletedNarNotReofferedAcrossClosures664=== RUN TestPresignedUploadRegisteredBeforeCommit665=== PAUSE TestPresignedUploadRegisteredBeforeCommit666=== RUN TestService_Rustfstest667=== PAUSE TestService_Rustfstest668=== RUN TestParseSize669=== PAUSE TestParseSize670=== RUN TestSkippedUploadsHandler671=== PAUSE TestSkippedUploadsHandler672=== RUN TestSystemdListenerNotActivated673--- PASS: TestSystemdListenerNotActivated (0.00s)674=== RUN TestWatchdogBeatsWhenHealthy675--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)676=== RUN TestWatchdogSkipsWhenUnhealthy6772026/10/07 07:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6782026/10/07 07:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6792026/10/07 07:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6802026/10/07 07:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6812026/10/07 07:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6822026/10/07 07:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6832026/10/07 07:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6842026/10/07 07:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6852026/10/07 07:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6862026/10/07 07:42:54 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"687--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)688=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle689=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle690=== RUN TestProxyWriteTimeout691=== PAUSE TestProxyWriteTimeout692=== RUN TestPendingClosureWriteTimeout693=== PAUSE TestPendingClosureWriteTimeout694=== RUN TestIsValidUploadKey695=== PAUSE TestIsValidUploadKey696=== RUN TestUploadHandlersRejectInvalidKeys697=== PAUSE TestUploadHandlersRejectInvalidKeys698=== RUN TestUploadHandlersRejectOversizedBody699=== PAUSE TestUploadHandlersRejectOversizedBody700=== RUN TestService_cleanupPendingClosuresHandler701=== PAUSE TestService_cleanupPendingClosuresHandler702=== RUN TestService_createPendingClosureHandler703=== PAUSE TestService_createPendingClosureHandler704=== RUN TestService_verifyS3Integrity705=== PAUSE TestService_verifyS3Integrity706=== RUN TestCompleteMultipartUnregistered707=== PAUSE TestCompleteMultipartUnregistered708=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT709=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT710=== CONT TestService_AuthMiddleware711=== CONT TestMetricsInventory712=== CONT TestDeduplicatedObjectsRecordedAsPending713=== CONT TestNARDeduplicationMetadataUploadBug714=== CONT TestCreatePendingClosureRejectsOversizedNAR715=== CONT TestCacheConfigHandlerMaxNarSize716=== CONT TestGenerateLandingPage717--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)7182026/10/07 07:42:54 INFO Received uploads request method=POST path=/api/pending_closures719=== CONT TestService_readinessHandler720=== CONT TestService_healthCheckHandler721=== CONT TestGracefulShutdownDrainsInflight722=== CONT TestGCTaskStore_Fail723=== CONT TestGCTaskStore_PhaseUpdates724=== CONT TestGCTaskStore_CompletedAllowsNewTask725=== CONT TestGCTaskStore_GetReturnsLatest726=== CONT TestGCTaskStore_GetEmpty727=== CONT TestGCTaskStore_ConflictDifferentParams728=== CONT TestGCTaskStore_DeduplicateSameParams729=== CONT TestGCTaskStore_StartNew730=== CONT TestGCEndsOnShutdown731=== CONT TestCommitRacingPendingCleanupKeepsObjects732=== CONT TestPushWaitsForSweepHoldingRow733=== CONT TestSweepRechecksPendingAfterLocking734=== CONT TestGetExistingObjectsLocksRows735=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT736=== CONT TestRegisterCompletedObjectNeedsPendingRow737--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)738--- PASS: TestGCTaskStore_Fail (0.00s)739--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)740--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)741--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)742--- PASS: TestGCTaskStore_GetEmpty (0.00s)743--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)744--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)745--- PASS: TestGCTaskStore_StartNew (0.00s)746=== CONT TestSweepSkipsRowsLockedByPush7472026/10/07 07:42:54 INFO Starting HTTP server address=127.0.0.1:39177748=== RUN TestGCEndsOnShutdown/before_the_run749=== PAUSE TestGCEndsOnShutdown/before_the_run750=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete751=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete752=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark753=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark7542026/10/07 07:42:54 INFO Shutdown signal received, draining in-flight requests timeout=10s755=== CONT TestForceGCDuringPushOffersSweptObject756=== CONT TestService_verifyS3Integrity757=== CONT TestFailedS3DeleteKeepsTombstone758=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows759=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows760=== CONT TestTombstonedObjectOfferedWithoutWaiting761=== CONT TestGCSweepSkipsPendingObjects762=== CONT TestReadRedirectKeepsNarinfoProxied763=== CONT TestCompleteMultipartUnregistered764=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection765=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check766=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check767=== CONT TestGCSweepDeliversEachKeyOnce768=== CONT TestService_createPendingClosureHandler769--- PASS: TestGenerateLandingPage (0.01s)770=== CONT TestService_cleanupPendingClosuresHandler771--- PASS: TestGracefulShutdownDrainsInflight (0.07s)772=== CONT TestUploadHandlersRejectOversizedBody773=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure774=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure775=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart776=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart777=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts778=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts779=== CONT TestUploadHandlersRejectInvalidKeys780=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info781=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info782=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal783=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal784=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key785=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key786=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key787=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key788=== CONT TestIsValidUploadKey789=== RUN TestIsValidUploadKey/narinfo790=== PAUSE TestIsValidUploadKey/narinfo791=== RUN TestIsValidUploadKey/nar_zst792=== PAUSE TestIsValidUploadKey/nar_zst793=== RUN TestIsValidUploadKey/nar_xz794=== PAUSE TestIsValidUploadKey/nar_xz795=== RUN TestIsValidUploadKey/nar_plain796=== PAUSE TestIsValidUploadKey/nar_plain797=== RUN TestIsValidUploadKey/listing798=== PAUSE TestIsValidUploadKey/listing799=== RUN TestIsValidUploadKey/build_log800=== PAUSE TestIsValidUploadKey/build_log801=== RUN TestIsValidUploadKey/build_log_home-manager_file802=== PAUSE TestIsValidUploadKey/build_log_home-manager_file803=== RUN TestIsValidUploadKey/build_log_plus_in_name804=== PAUSE TestIsValidUploadKey/build_log_plus_in_name805=== RUN TestIsValidUploadKey/build_log_question_mark806=== PAUSE TestIsValidUploadKey/build_log_question_mark807=== RUN TestIsValidUploadKey/build_log_equals808=== PAUSE TestIsValidUploadKey/build_log_equals809=== RUN TestIsValidUploadKey/realisation810=== PAUSE TestIsValidUploadKey/realisation811=== RUN TestIsValidUploadKey/realisation_plus_in_output812=== PAUSE TestIsValidUploadKey/realisation_plus_in_output813=== RUN TestIsValidUploadKey/nix-cache-info814=== PAUSE TestIsValidUploadKey/nix-cache-info815=== RUN TestIsValidUploadKey/index.html816=== PAUSE TestIsValidUploadKey/index.html817=== RUN TestIsValidUploadKey/narinfo_key,_nar_type818=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type819=== RUN TestIsValidUploadKey/nar_key,_narinfo_type820=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type821=== RUN TestIsValidUploadKey/listing_key,_narinfo_type822=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type823=== RUN TestIsValidUploadKey/traversal824=== PAUSE TestIsValidUploadKey/traversal825=== RUN TestIsValidUploadKey/traversal_nar826=== PAUSE TestIsValidUploadKey/traversal_nar827=== RUN TestIsValidUploadKey/absolute828=== PAUSE TestIsValidUploadKey/absolute829=== RUN TestIsValidUploadKey/empty_key830=== PAUSE TestIsValidUploadKey/empty_key831=== RUN TestIsValidUploadKey/unknown_type832=== PAUSE TestIsValidUploadKey/unknown_type833=== CONT TestPendingClosureWriteTimeout834=== RUN TestPendingClosureWriteTimeout/empty835=== PAUSE TestPendingClosureWriteTimeout/empty836=== RUN TestPendingClosureWriteTimeout/400_objects837=== PAUSE TestPendingClosureWriteTimeout/400_objects838=== RUN TestPendingClosureWriteTimeout/670k_objects839=== PAUSE TestPendingClosureWriteTimeout/670k_objects840=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline841=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline842=== CONT TestProxyWriteTimeout843=== RUN TestProxyWriteTimeout/narinfo844=== PAUSE TestProxyWriteTimeout/narinfo845=== RUN TestProxyWriteTimeout/1_GiB_nar846=== PAUSE TestProxyWriteTimeout/1_GiB_nar847=== RUN TestProxyWriteTimeout/10_GiB_nar848=== PAUSE TestProxyWriteTimeout/10_GiB_nar849=== RUN TestProxyWriteTimeout/unknown_size850=== PAUSE TestProxyWriteTimeout/unknown_size851=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle852=== NAME TestNARDeduplicationMetadataUploadBug853 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug218271668/001/store/3zsf9m38qb3bd22a08vpmffhmwnpc0sw-file1.txt8542026/10/07 07:42:54 INFO Received uploads request method=POST path=/api/pending_closures855--- PASS: TestMetricsInventory (0.38s)856=== CONT TestSkippedUploadsHandler8572026/10/07 07:42:54 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000858--- PASS: TestSkippedUploadsHandler (0.00s)859=== CONT TestParseSize860--- PASS: TestParseSize (0.00s)861=== CONT TestService_Rustfstest862--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.39s)863=== CONT TestPresignedUploadRegisteredBeforeCommit8642026/10/07 07:42:54 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"865--- PASS: TestService_AuthMiddleware (0.40s)866=== CONT TestCompletedNarNotReofferedAcrossClosures8672026/10/07 07:42:55 WARN readiness check failed error="closed pool"868--- PASS: TestService_readinessHandler (0.59s)869=== CONT TestCompleteMultipartUpload_ErrorButObjectExists870--- PASS: TestService_healthCheckHandler (0.62s)871=== CONT TestRedundantMultipartUpload8722026/10/07 07:42:55 INFO Received push request method=POST path=/api/pushes8732026/10/07 07:42:55 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)8742026/10/07 07:42:55 INFO Uploading 3zsf9m38qb3bd22a08vpmffhmwnpc0sw-file1.txt (160B)8752026/10/07 07:42:55 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"8762026/10/07 07:42:55 WARN Failed to register uploaded object key=3zsf9m38qb3bd22a08vpmffhmwnpc0sw.ls error="server returned 404: 404 page not found\n"8772026/10/07 07:42:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8782026/10/07 07:42:55 INFO Signed narinfos id=1 count=18792026/10/07 07:42:55 INFO Uploading 1 narinfos8802026/10/07 07:42:55 INFO Received complete push request method=POST path=/api/pushes/1/complete8812026/10/07 07:42:55 WARN Failed to register uploaded object key=3zsf9m38qb3bd22a08vpmffhmwnpc0sw.narinfo error="server returned 404: 404 page not found\n"8822026/10/07 07:42:55 INFO Completed push id=1 objects=3 duration=6.492269ms8832026/10/07 07:42:55 INFO Upload complete. (91ms)884=== NAME TestNARDeduplicationMetadataUploadBug885 metadata_upload_test.go:54: Retrieved narinfo from S3:886 StorePath: /build/TestNARDeduplicationMetadataUploadBug218271668/001/store/3zsf9m38qb3bd22a08vpmffhmwnpc0sw-file1.txt887 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst888 Compression: zstd889 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf890 NarSize: 160891 References: 892 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf893 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)894 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):895 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}8962026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures8972026/10/07 07:42:55 INFO Aborted multipart uploads count=0 kept=08982026/10/07 07:42:55 WARN Force mode enabled - objects will be deleted immediately without grace period899 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug218271668/001/store/vvhwivdshlzdg7ck2546960vcsra30ws-file2.txt9002026/10/07 07:42:55 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=09012026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures9022026/10/07 07:42:55 INFO Vacuumed table table=pending_closures9032026/10/07 07:42:55 INFO Vacuumed table table=pending_objects9042026/10/07 07:42:55 INFO Vacuumed table table=multipart_uploads9052026/10/07 07:42:55 INFO Vacuumed table table=closures9062026/10/07 07:42:55 INFO Vacuumed table table=objects907--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.71s)908=== CONT TestPush_SignsNarinfosOfItsPendingObjects909--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.72s)910=== CONT TestPush_RejectsBadRequests911--- PASS: TestReadRedirectKeepsNarinfoProxied (0.73s)912=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9132026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures9142026/10/07 07:42:55 INFO Aborted multipart uploads count=0 kept=09152026/10/07 07:42:55 WARN Force mode enabled - objects will be deleted immediately without grace period9162026/10/07 07:42:55 INFO Received push request method=POST path=/api/pushes9172026/10/07 07:42:55 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."9182026/10/07 07:42:55 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."9192026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures9202026/10/07 07:42:55 INFO Aborted multipart uploads count=0 kept=0921--- PASS: TestFailedS3DeleteKeepsTombstone (0.77s)9222026/10/07 07:42:55 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)923=== CONT TestPush_RootsAreLockedInByteOrder9242026/10/07 07:42:55 WARN Force mode enabled - objects will be deleted immediately without grace period9252026/10/07 07:42:55 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign9262026/10/07 07:42:55 INFO Signed narinfos id=2 count=19272026/10/07 07:42:55 WARN Failed to register uploaded object key=vvhwivdshlzdg7ck2546960vcsra30ws.ls error="server returned 404: 404 page not found\n"9282026/10/07 07:42:55 INFO Uploading 1 narinfos9292026/10/07 07:42:55 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=09302026/10/07 07:42:55 INFO Received complete push request method=POST path=/api/pushes/2/complete9312026/10/07 07:42:55 WARN Failed to register uploaded object key=vvhwivdshlzdg7ck2546960vcsra30ws.narinfo error="server returned 404: 404 page not found\n"9322026/10/07 07:42:55 INFO Completed push id=2 objects=3 duration=2.124093ms9332026/10/07 07:42:55 INFO Vacuumed table table=pending_closures9342026/10/07 07:42:55 INFO Upload complete. (52ms)935=== NAME TestNARDeduplicationMetadataUploadBug936 metadata_upload_test.go:76: Retrieved narinfo from S3:937 StorePath: /build/TestNARDeduplicationMetadataUploadBug218271668/001/store/vvhwivdshlzdg7ck2546960vcsra30ws-file2.txt938 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst939 Compression: zstd940 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf941 NarSize: 160942 References: 943 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf9442026/10/07 07:42:55 INFO Vacuumed table table=pending_objects9452026/10/07 07:42:55 INFO Vacuumed table table=multipart_uploads9462026/10/07 07:42:55 INFO Vacuumed table table=closures947 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)948 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):949 {"version":1,"root":{"type":"regular","size":44}}950--- PASS: TestNARDeduplicationMetadataUploadBug (0.80s)951=== CONT TestPush_CompleteWaitsForCleanupOfThePush9522026/10/07 07:42:55 INFO Vacuumed table table=objects953--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.80s)954=== CONT TestPush_RepeatedRootCommitsOnce955--- PASS: TestGCSweepSkipsPendingObjects (0.80s)956=== CONT TestPush_CompleteCommitsEveryRoot9572026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures958--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.84s)959=== CONT TestPush_OverlappingRootsStoreOneRowPerKey9602026/10/07 07:42:55 INFO Aborted multipart uploads count=0 kept=09612026/10/07 07:42:55 WARN Force mode enabled - objects will be deleted immediately without grace period9622026/10/07 07:42:55 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=09632026/10/07 07:42:55 INFO Vacuumed table table=pending_closures964--- PASS: TestGetExistingObjectsLocksRows (0.90s)965=== CONT TestReadRedirectUsesPublicS3URL9662026/10/07 07:42:55 INFO Vacuumed table table=pending_objects9672026/10/07 07:42:55 INFO Vacuumed table table=multipart_uploads9682026/10/07 07:42:55 INFO Vacuumed table table=closures9692026/10/07 07:42:55 INFO Vacuumed table table=objects9702026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures9712026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures9722026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures973--- PASS: TestSweepRechecksPendingAfterLocking (0.90s)974=== CONT TestReadProxyRangeRequest9752026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures9762026/10/07 07:42:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9772026/10/07 07:42:55 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst978--- PASS: TestCompleteMultipartUnregistered (0.96s)979=== CONT TestObjectStatsLargeCommit9802026/10/07 07:42:55 INFO Received cleanup request method=DELETE path=/api/pending_closures9812026/10/07 07:42:55 INFO Aborted multipart uploads count=0 kept=09822026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures9832026/10/07 07:42:55 INFO Received cleanup request method=DELETE path=/api/pending_closures9842026/10/07 07:42:55 INFO Aborted multipart uploads count=1 kept=09852026/10/07 07:42:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9862026-10-07 07:42:55.537 UTC [688] ERROR: Closure does not exist: id=19872026-10-07 07:42:55.537 UTC [688] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9882026-10-07 07:42:55.537 UTC [688] STATEMENT: -- name: CommitPendingClosure :one989 SELECT commit_pending_closure($1::bigint)::bigint990 991--- PASS: TestService_cleanupPendingClosuresHandler (1.01s)992=== CONT TestPresentNotReportedWhileGCDeletesClosure993=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale994=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale995=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh996=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh997=== CONT TestPresentRefreshesOnlyStaleClosures9982026/10/07 07:42:55 INFO Aborted multipart uploads count=0 kept=09992026/10/07 07:42:55 WARN Force mode enabled - objects will be deleted immediately without grace period10002026/10/07 07:42:55 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=010012026/10/07 07:42:55 INFO Vacuumed table table=pending_closures10022026/10/07 07:42:55 INFO Vacuumed table table=pending_objects10032026/10/07 07:42:55 INFO Vacuumed table table=multipart_uploads10042026/10/07 07:42:55 INFO Vacuumed table table=closures10052026/10/07 07:42:55 INFO Vacuumed table table=objects1006--- PASS: TestGCSweepDeliversEachKeyOnce (1.06s)1007=== CONT TestPresentReportsOnlyClosureRoots10082026/10/07 07:42:55 INFO Aborted multipart uploads count=0 kept=010092026/10/07 07:42:55 WARN Force mode enabled - objects will be deleted immediately without grace period10102026/10/07 07:42:55 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010112026/10/07 07:42:55 INFO Vacuumed table table=pending_closures10122026/10/07 07:42:55 INFO Vacuumed table table=pending_objects10132026/10/07 07:42:55 INFO Vacuumed table table=multipart_uploads10142026/10/07 07:42:55 INFO Vacuumed table table=closures10152026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures10162026/10/07 07:42:55 INFO Vacuumed table table=objects10172026/10/07 07:42:55 INFO Aborted multipart uploads count=0 kept=010182026/10/07 07:42:55 WARN Force mode enabled - objects will be deleted immediately without grace period10192026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures10202026/10/07 07:42:55 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=010212026/10/07 07:42:55 INFO Vacuumed table table=pending_closures10222026/10/07 07:42:55 INFO Vacuumed table table=pending_objects10232026/10/07 07:42:55 INFO Vacuumed table table=multipart_uploads10242026/10/07 07:42:55 INFO Vacuumed table table=closures10252026/10/07 07:42:55 INFO Vacuumed table table=objects1026--- PASS: TestSweepSkipsRowsLockedByPush (1.24s)1027=== CONT TestCreatePin_ReservedPins10282026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures10292026/10/07 07:42:55 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10302026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures1031--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.91s)1032=== CONT TestOrphanedObjectsGCStressTest1033--- PASS: TestService_Rustfstest (0.91s)1034=== CONT TestOrphanedObjectsGC10352026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures10362026/10/07 07:42:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43771/oidc10372026/10/07 07:42:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10382026/10/07 07:42:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10392026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures10402026/10/07 07:42:55 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NmExMDI4MTgtNTMwMS00ODJiLWIzY2ItM2U1MjdlNzMwZWFjLjEzYmYxYzVmLTIzNjctNGQ5ZC05YjUyLWI2YThlZjEwNTAzNHgxNzkxMzU4OTc1MzAyNTkwNTIz parts=1010412026/10/07 07:42:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10422026/10/07 07:42:55 INFO Completed upload id=1 objects=2 duration=6.063498ms10432026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures10442026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures10452026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures10462026/10/07 07:42:55 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10472026/10/07 07:42:55 WARN Found objects in DB but missing from S3, will re-upload count=11048--- PASS: TestService_verifyS3Integrity (1.38s)10492026/10/07 07:42:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1050=== CONT TestPinProtectsFromGC10512026/10/07 07:42:55 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NmExMDI4MTgtNTMwMS00ODJiLWIzY2ItM2U1MjdlNzMwZWFjLjBhNzUyNWM1LTY2ZTMtNDJjNS1iMDRlLTU5YWY1MDJlODBhNXgxNzkxMzU4OTc1ODgzNDc0MDg310522026/10/07 07:42:55 INFO Received uploads request method=POST path=/api/pending_closures1053=== RUN TestPush_RejectsBadRequests/root_not_in_objects1054=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1055=== RUN TestPush_RejectsBadRequests/no_roots1056=== PAUSE TestPush_RejectsBadRequests/no_roots1057=== RUN TestPush_RejectsBadRequests/no_objects1058=== PAUSE TestPush_RejectsBadRequests/no_objects1059=== RUN TestPush_RejectsBadRequests/bad_root10602026/10/07 07:42:55 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NmExMDI4MTgtNTMwMS00ODJiLWIzY2ItM2U1MjdlNzMwZWFjLjBhNzUyNWM1LTY2ZTMtNDJjNS1iMDRlLTU5YWY1MDJlODBhNXgxNzkxMzU4OTc1ODgzNDc0MDg3 parts=11061=== PAUSE TestPush_RejectsBadRequests/bad_root1062=== CONT TestPushDedupSurvivesConcurrentGC1063--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.82s)1064=== CONT TestGCMetrics1065--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.41s)1066=== CONT TestGCBugBareHashReferences10672026/10/07 07:42:55 INFO Received push request method=POST path=/api/pushes1068--- PASS: TestPushWaitsForSweepHoldingRow (1.48s)1069=== CONT TestGCAdvisoryLockBlocksConcurrentRun10702026/10/07 07:42:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10712026/10/07 07:42:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10722026/10/07 07:42:56 INFO Signed narinfos id=1 count=110732026/10/07 07:42:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10742026/10/07 07:42:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10752026/10/07 07:42:56 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10762026/10/07 07:42:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10772026/10/07 07:42:56 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10782026/10/07 07:42:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10792026/10/07 07:42:56 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110802026/10/07 07:42:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10812026/10/07 07:42:56 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1082--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.78s)1083=== CONT TestParseSingleRange1084=== RUN TestParseSingleRange/none1085=== PAUSE TestParseSingleRange/none1086=== RUN TestParseSingleRange/unknown_unit1087=== PAUSE TestParseSingleRange/unknown_unit1088=== RUN TestParseSingleRange/multi-range_ignored1089=== PAUSE TestParseSingleRange/multi-range_ignored1090=== RUN TestParseSingleRange/malformed_no_dash10912026/10/07 07:42:56 INFO Received push request method=POST path=/api/pushes1092=== PAUSE TestParseSingleRange/malformed_no_dash1093=== RUN TestParseSingleRange/malformed_both_empty1094=== PAUSE TestParseSingleRange/malformed_both_empty1095=== RUN TestParseSingleRange/malformed_end_before_start1096=== PAUSE TestParseSingleRange/malformed_end_before_start1097=== RUN TestParseSingleRange/closed1098=== PAUSE TestParseSingleRange/closed1099=== RUN TestParseSingleRange/open-ended1100=== PAUSE TestParseSingleRange/open-ended1101=== RUN TestParseSingleRange/end_clamped_to_size1102=== PAUSE TestParseSingleRange/end_clamped_to_size1103=== RUN TestParseSingleRange/suffix1104=== PAUSE TestParseSingleRange/suffix1105=== RUN TestParseSingleRange/suffix_exceeds_size1106=== PAUSE TestParseSingleRange/suffix_exceeds_size1107=== RUN TestParseSingleRange/single_byte1108=== PAUSE TestParseSingleRange/single_byte1109=== RUN TestParseSingleRange/start_past_EOF1110=== PAUSE TestParseSingleRange/start_past_EOF1111=== RUN TestParseSingleRange/start_far_past_EOF1112=== PAUSE TestParseSingleRange/start_far_past_EOF1113=== CONT TestLeadEndsOnShutdown11142026/10/07 07:42:56 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NmExMDI4MTgtNTMwMS00ODJiLWIzY2ItM2U1MjdlNzMwZWFjLjY4MzExMWFlLWRkMTQtNDQwOS05NzdkLTYwMWRiM2Y2NTg0OHgxNzkxMzU4OTc1NDM5NDIzNDk2 parts=1011152026/10/07 07:42:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11162026/10/07 07:42:56 INFO Received complete push request method=POST path=/api/pushes/1/complete11172026/10/07 07:42:56 INFO Completed upload id=1 objects=2 duration=6.947609ms11182026/10/07 07:42:56 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011192026/10/07 07:42:56 INFO Received push request method=POST path=/api/pushes11202026/10/07 07:42:56 INFO Received uploads request method=POST path=/api/pending_closures11212026/10/07 07:42:56 INFO Starting cleanup of old closures method=DELETE path=/api/closures11222026/10/07 07:42:56 INFO Completed push id=1 objects=4 duration=9.965373ms11232026/10/07 07:42:56 INFO Received push request method=POST path=/api/pushes11242026/10/07 07:42:56 INFO Aborted multipart uploads count=0 kept=011252026/10/07 07:42:56 INFO Received push request method=POST path=/api/pushes11262026/10/07 07:42:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011272026/10/07 07:42:56 INFO Vacuumed table table=pending_closures11282026/10/07 07:42:56 INFO Vacuumed table table=pending_objects11292026/10/07 07:42:56 INFO Vacuumed table table=multipart_uploads11302026/10/07 07:42:56 INFO Vacuumed table table=closures11312026/10/07 07:42:56 INFO Vacuumed table table=objects11322026-10-07 07:42:56.096 UTC [824] ERROR: could not obtain lock on row in relation "closures"11332026-10-07 07:42:56.096 UTC [824] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11342026-10-07 07:42:56.096 UTC [824] ERROR: could not obtain lock on row in relation "closures"11352026-10-07 07:42:56.096 UTC [824] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11362026-10-07 07:42:56.097 UTC [824] ERROR: could not obtain lock on row in relation "closures"11372026-10-07 07:42:56.097 UTC [824] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11382026-10-07 07:42:56.097 UTC [824] ERROR: could not obtain lock on row in relation "closures"11392026-10-07 07:42:56.097 UTC [824] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11402026-10-07 07:42:56.097 UTC [824] ERROR: could not obtain lock on row in relation "closures"11412026-10-07 07:42:56.097 UTC [824] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11422026/10/07 07:42:56 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001143--- PASS: TestService_createPendingClosureHandler (1.57s)1144=== CONT TestReadRedirectNar1145--- PASS: TestPush_RootsAreLockedInByteOrder (0.81s)1146=== CONT TestLeadIncumbentAnnouncesAtOnce11472026/10/07 07:42:56 INFO Received push request method=POST path=/api/pushes11482026/10/07 07:42:56 INFO Aborted multipart uploads count=0 kept=011492026/10/07 07:42:56 INFO Received complete push request method=POST path=/api/pushes/1/complete11502026/10/07 07:42:56 WARN Force mode enabled - objects will be deleted immediately without grace period11512026/10/07 07:42:56 INFO Completed push id=1 objects=4 duration=8.637221ms1152--- PASS: TestPush_RepeatedRootCommitsOnce (0.81s)1153=== CONT TestReadProxyDisabled11542026/10/07 07:42:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=2 objects-deleted-after-grace-period=2 objects-failed-to-delete=011552026/10/07 07:42:56 INFO Vacuumed table table=pending_closures11562026/10/07 07:42:56 INFO Vacuumed table table=pending_objects11572026/10/07 07:42:56 INFO Received push request method=POST path=/api/pushes11582026/10/07 07:42:56 INFO Vacuumed table table=multipart_uploads11592026/10/07 07:42:56 INFO Vacuumed table table=closures11602026/10/07 07:42:56 INFO Vacuumed table table=objects11612026/10/07 07:42:56 INFO Received complete push request method=POST path=/api/pushes/2/complete11622026/10/07 07:42:56 INFO Completed push id=2 objects=4 duration=12.577676ms1163--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.93s)1164=== CONT TestLeadElectsOneAndHandsOver11652026/10/07 07:42:56 INFO Received complete push request method=POST path=/api/pushes/1/complete11662026/10/07 07:42:56 INFO Received push request method=POST path=/api/pushes11672026/10/07 07:42:56 INFO Completed push id=1 objects=6 duration=7.985241ms1168--- PASS: TestPush_CompleteCommitsEveryRoot (0.86s)1169=== CONT TestConnectWaitsForAPeerMigration1170--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.86s)1171=== CONT TestReadProxyRootRedirectsToIndexHTML1172--- PASS: TestReadRedirectUsesPublicS3URL (0.81s)1173=== CONT TestResolveDBConnectionString1174=== RUN TestResolveDBConnectionString/flag_wins1175=== PAUSE TestResolveDBConnectionString/flag_wins1176=== RUN TestResolveDBConnectionString/file_when_flag_empty1177=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1178=== RUN TestResolveDBConnectionString/missing_file_is_an_error1179=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1180=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1181=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1182=== RUN TestResolveDBConnectionString/nothing_configured1183=== PAUSE TestResolveDBConnectionString/nothing_configured1184=== CONT TestReadProxyConditionalGet1185--- PASS: TestReadProxyRangeRequest (0.83s)1186=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock11872026-10-07 07:42:56.400 UTC [903] ERROR: Push does not exist: id=111882026-10-07 07:42:56.400 UTC [903] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11892026-10-07 07:42:56.400 UTC [903] STATEMENT: SELECT commit_push($1)1190--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.08s)1191=== CONT TestReadProxyOutlastsServerWriteTimeout1192--- PASS: TestPresentRefreshesOnlyStaleClosures (0.95s)1193=== CONT TestDeleteClosuresRacingPins1194--- PASS: TestPresentReportsOnlyClosureRoots (0.92s)1195=== CONT TestReadProxyHead11962026/10/07 07:42:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11972026/10/07 07:42:56 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NmExMDI4MTgtNTMwMS00ODJiLWIzY2ItM2U1MjdlNzMwZWFjLjYzMjEzNTIwLWQ1ZTYtNDQ2NC1hMDA5LWIwZjgyZTY0YjFiNHgxNzkxMzU4OTc1ODUwOTA1MTg2 parts=1211982026/10/07 07:42:56 INFO Received uploads request method=POST path=/api/pending_closures1199--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.63s)1200=== CONT TestClientFallsBackToClosures12012026/10/07 07:42:56 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12022026/10/07 07:42:56 WARN Refused reserved pin name=worker-x86_64-linux12032026/10/07 07:42:56 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12042026/10/07 07:42:56 INFO Received create pin request method=POST path=/api/pins/my-app12052026/10/07 07:42:56 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1206--- PASS: TestCreatePin_ReservedPins (0.83s)1207=== CONT TestClientPushesUseOnePush12082026/10/07 07:42:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12092026/10/07 07:42:56 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NmExMDI4MTgtNTMwMS00ODJiLWIzY2ItM2U1MjdlNzMwZWFjLmQ2YjEzMzEyLWNmZTMtNGEyNC04YTc3LTc2NWZkOWY0MDg5MXgxNzkxMzU4OTc1OTA3NjA0NDI3 parts=1212102026/10/07 07:42:56 INFO Received uploads request method=POST path=/api/pending_closures12112026/10/07 07:42:56 INFO Received uploads request method=POST path=/api/pending_closures12122026/10/07 07:42:56 INFO Received uploads request method=POST path=/api/pending_closures12132026/10/07 07:42:56 INFO Aborted multipart uploads count=0 kept=012142026/10/07 07:42:56 WARN Force mode enabled - objects will be deleted immediately without grace period12152026/10/07 07:42:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012162026/10/07 07:42:56 INFO Vacuumed table table=pending_closures12172026/10/07 07:42:56 INFO Vacuumed table table=pending_objects12182026/10/07 07:42:56 INFO Vacuumed table table=multipart_uploads12192026/10/07 07:42:56 INFO Vacuumed table table=closures12202026/10/07 07:42:56 INFO Vacuumed table table=objects1221--- PASS: TestGCMetrics (0.75s)1222=== CONT TestReadProxyInvalidPath12232026/10/07 07:42:56 INFO Aborted multipart uploads count=0 kept=012242026/10/07 07:42:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012252026/10/07 07:42:56 INFO Vacuumed table table=pending_closures12262026/10/07 07:42:56 INFO Vacuumed table table=pending_objects12272026/10/07 07:42:56 INFO Vacuumed table table=multipart_uploads12282026/10/07 07:42:56 INFO Vacuumed table table=closures12292026/10/07 07:42:56 INFO Vacuumed table table=objects12302026/10/07 07:42:56 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=nixbld database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1231--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.74s)1232=== CONT TestReadProxyContentNegotiation12332026/10/07 07:42:56 INFO Aborted multipart uploads count=0 kept=012342026/10/07 07:42:56 WARN Force mode enabled - objects will be deleted immediately without grace period12352026/10/07 07:42:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012362026/10/07 07:42:56 INFO Vacuumed table table=pending_closures12372026/10/07 07:42:56 INFO Vacuumed table table=pending_objects12382026/10/07 07:42:56 INFO Vacuumed table table=multipart_uploads12392026/10/07 07:42:56 INFO Vacuumed table table=closures12402026/10/07 07:42:56 INFO Vacuumed table table=objects1241=== NAME TestPinProtectsFromGC1242 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC3104024167/001/store/c5zg1790qpgrs3y7smf94rj4fx36d8ak-pinned-file.txt1243 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC3104024167/001/store/s350ja0gfrskvsn36c3q3rh3x5h67zq6-unpinned-file.txt1244--- PASS: TestPushDedupSurvivesConcurrentGC (0.83s)1245=== CONT TestReadProxyNarinfoAlreadyDecompressed12462026/10/07 07:42:56 INFO lead: acquired remote=192.0.2.1:12341247--- PASS: TestReadRedirectNar (0.70s)1248=== CONT TestReadProxy40412492026/10/07 07:42:56 INFO lead: acquired remote=192.0.2.1:123412502026/10/07 07:42:56 INFO lead: released remote=192.0.2.1:12341251--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.72s)1252=== CONT TestReadProxyNarStreaming12532026/10/07 07:42:56 INFO Received push request method=POST path=/api/pushes12542026/10/07 07:42:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12552026/10/07 07:42:56 INFO Uploading c5zg1790qpgrs3y7smf94rj4fx36d8ak-pinned-file.txt (128B)1256--- PASS: TestReadProxyDisabled (0.71s)1257=== CONT TestReadProxyNarinfo12582026/10/07 07:42:56 WARN Failed to register uploaded object key=c5zg1790qpgrs3y7smf94rj4fx36d8ak.ls error="server returned 404: 404 page not found\n"12592026/10/07 07:42:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12602026/10/07 07:42:56 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"12612026/10/07 07:42:56 INFO Signed narinfos id=1 count=112622026/10/07 07:42:56 INFO Uploading 1 narinfos12632026/10/07 07:42:56 INFO Received complete push request method=POST path=/api/pushes/1/complete12642026/10/07 07:42:56 WARN Failed to register uploaded object key=c5zg1790qpgrs3y7smf94rj4fx36d8ak.narinfo error="server returned 404: 404 page not found\n"12652026/10/07 07:42:56 INFO Completed push id=1 objects=3 duration=11.034634ms12662026/10/07 07:42:56 INFO Upload complete. (75ms)1267=== NAME TestOrphanedObjectsGC1268 orphaned_objects_gc_test.go:287: GC Test Summary:1269 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1270 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1271 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1272 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1273 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1274--- PASS: TestOrphanedObjectsGC (1.06s)1275=== CONT TestCacheStatsHandler12762026/10/07 07:42:56 INFO lead: acquired remote=192.0.2.1:12341277--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.68s)1278=== CONT TestIsValidCachePath1279=== RUN TestIsValidCachePath/narinfo1280=== PAUSE TestIsValidCachePath/narinfo1281=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1282=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1283=== RUN TestIsValidCachePath/nar_zst1284=== PAUSE TestIsValidCachePath/nar_zst1285=== RUN TestIsValidCachePath/nar_xz1286=== PAUSE TestIsValidCachePath/nar_xz1287=== RUN TestIsValidCachePath/nar_bz21288=== PAUSE TestIsValidCachePath/nar_bz21289=== RUN TestIsValidCachePath/nar_uncompressed1290=== PAUSE TestIsValidCachePath/nar_uncompressed1291=== RUN TestIsValidCachePath/ls1292=== PAUSE TestIsValidCachePath/ls1293=== RUN TestIsValidCachePath/log1294=== PAUSE TestIsValidCachePath/log1295=== RUN TestIsValidCachePath/realisation1296=== PAUSE TestIsValidCachePath/realisation1297=== RUN TestIsValidCachePath/nix-cache-info1298=== PAUSE TestIsValidCachePath/nix-cache-info1299=== RUN TestIsValidCachePath/index.html1300=== PAUSE TestIsValidCachePath/index.html1301=== RUN TestIsValidCachePath/traversal_parent1302=== PAUSE TestIsValidCachePath/traversal_parent1303=== RUN TestIsValidCachePath/traversal_in_middle1304=== PAUSE TestIsValidCachePath/traversal_in_middle1305=== RUN TestIsValidCachePath/invalid_char_e1306=== PAUSE TestIsValidCachePath/invalid_char_e1307=== RUN TestIsValidCachePath/invalid_char_u1308=== PAUSE TestIsValidCachePath/invalid_char_u1309=== RUN TestIsValidCachePath/random_path1310=== PAUSE TestIsValidCachePath/random_path1311=== RUN TestIsValidCachePath/empty1312=== PAUSE TestIsValidCachePath/empty1313=== RUN TestIsValidCachePath/leading_slash1314=== PAUSE TestIsValidCachePath/leading_slash1315=== RUN TestIsValidCachePath/wrong_extension1316=== PAUSE TestIsValidCachePath/wrong_extension1317=== RUN TestIsValidCachePath/short_hash1318=== PAUSE TestIsValidCachePath/short_hash1319=== CONT TestClientSharedPathCommittedMidPush1320--- PASS: TestReadProxyConditionalGet (0.68s)1321=== CONT TestClientWithDependencies1322--- PASS: TestGCBugBareHashReferences (1.01s)1323=== CONT TestService_AuthMiddleware_OIDC13242026/10/07 07:42:56 INFO Received push request method=POST path=/api/pushes13252026/10/07 07:42:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13262026/10/07 07:42:56 INFO Uploading s350ja0gfrskvsn36c3q3rh3x5h67zq6-unpinned-file.txt (128B)13272026/10/07 07:42:56 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"13282026/10/07 07:42:56 WARN Failed to register uploaded object key=s350ja0gfrskvsn36c3q3rh3x5h67zq6.ls error="server returned 404: 404 page not found\n"13292026/10/07 07:42:56 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13302026/10/07 07:42:56 INFO Signed narinfos id=2 count=113312026/10/07 07:42:56 INFO Uploading 1 narinfos13322026/10/07 07:42:56 INFO Received complete push request method=POST path=/api/pushes/2/complete13332026/10/07 07:42:56 WARN Failed to register uploaded object key=s350ja0gfrskvsn36c3q3rh3x5h67zq6.narinfo error="server returned 404: 404 page not found\n"13342026/10/07 07:42:56 INFO Completed push id=2 objects=3 duration=5.419837ms13352026/10/07 07:42:56 INFO Upload complete. (58ms)13362026/10/07 07:42:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures13372026/10/07 07:42:57 INFO Garbage collection started1338--- PASS: TestReadProxyHead (0.53s)1339=== CONT TestClientMultipleUploads13402026/10/07 07:42:57 INFO Aborted multipart uploads count=0 kept=013412026/10/07 07:42:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39795/oidc13422026/10/07 07:42:57 WARN Force mode enabled - objects will be deleted immediately without grace period13432026/10/07 07:42:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13442026/10/07 07:42:57 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=013452026/10/07 07:42:57 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NmExMDI4MTgtNTMwMS00ODJiLWIzY2ItM2U1MjdlNzMwZWFjLjUyMzBmMDE3LTNlNDktNDVjMS1hMGU2LTQyNGI1MmEwMTNlNXgxNzkxMzU4OTc2NjU2MzMzNDIy error="Get \"http://127.0.0.1:1/bucket32/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"13462026/10/07 07:42:57 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NmExMDI4MTgtNTMwMS00ODJiLWIzY2ItM2U1MjdlNzMwZWFjLjg4MDAyNzRjLTI1YTUtNDhjMy1iYTQzLTE0NzA2MDRmYzY2N3gxNzkxMzU4OTc2NjQ4ODg5NjEy parts=1213472026/10/07 07:42:57 INFO Received cleanup request method=DELETE path=/api/pending_closures13482026/10/07 07:42:57 INFO Vacuumed table table=pending_closures13492026/10/07 07:42:57 INFO Aborted multipart uploads count=1 kept=013502026/10/07 07:42:57 INFO Vacuumed table table=pending_objects13512026/10/07 07:42:57 INFO Vacuumed table table=multipart_uploads1352--- PASS: TestRedundantMultipartUpload (1.94s)1353=== CONT TestClientIntegration13542026/10/07 07:42:57 INFO Vacuumed table table=closures13552026/10/07 07:42:57 INFO Vacuumed table table=objects1356--- PASS: TestReadProxyInvalidPath (0.43s)1357=== CONT TestCacheConfigHandler1358=== RUN TestCacheConfigHandler/full_config,_no_issuer1359=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1360=== RUN TestCacheConfigHandler/no_cache_url_configured1361=== PAUSE TestCacheConfigHandler/no_cache_url_configured1362=== RUN TestCacheConfigHandler/no_signing_keys1363=== PAUSE TestCacheConfigHandler/no_signing_keys1364=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1365=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1366=== CONT TestClientErrorHandling1367=== RUN TestClientErrorHandling/InvalidStorePath1368=== PAUSE TestClientErrorHandling/InvalidStorePath1369=== RUN TestClientErrorHandling/InvalidAuthToken1370=== PAUSE TestClientErrorHandling/InvalidAuthToken1371=== RUN TestClientErrorHandling/ServerNotAvailable1372=== PAUSE TestClientErrorHandling/ServerNotAvailable1373=== CONT TestClientCADerivations1374--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.41s)1375=== CONT TestService_ReadScope_PublicByDefault1376--- PASS: TestReadProxyContentNegotiation (0.44s)1377=== CONT TestService_RequireScope_OIDC1378--- PASS: TestReadProxy404 (0.41s)1379=== CONT TestMultipartCleanup1380--- PASS: TestReadProxyNarStreaming (0.41s)1381=== CONT TestMetricsCommit13822026/10/07 07:42:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40493/oidc1383--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (1.02s)1384=== CONT TestObjectStatsTrigger13852026/10/07 07:42:57 INFO Received uploads request method=POST path=/api/pending_closures13862026/10/07 07:42:57 INFO Received uploads request method=POST path=/api/pending_closures13872026/10/07 07:42:57 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13882026/10/07 07:42:57 INFO Uploading wyckaldncfljyylgcq2mrmcvgjdazaj2-shared-dep (136B)13892026/10/07 07:42:57 INFO Uploading vjysxxcdkfbaxqgmipwscgkd7rdfp9pg-b (216B)13902026/10/07 07:42:57 WARN Failed to register uploaded object key=8ygl8pshdhfh9a9mz3zqczpzgdbvm4f1.ls error="server returned 404: 404 page not found\n"1391--- PASS: TestCacheStatsHandler (0.42s)13922026/10/07 07:42:57 WARN Failed to register uploaded object key=nar/03i4hszxd61ydmr5hq1xrh2mm6dx8s6aq9shd3vp5mk9w4q7m9pv.nar.zst error="server returned 404: 404 page not found\n"1393=== CONT TestPendingCleanupUsesOneCutoff13942026/10/07 07:42:57 WARN Failed to register uploaded object key=wyckaldncfljyylgcq2mrmcvgjdazaj2.ls error="server returned 404: 404 page not found\n"13952026/10/07 07:42:57 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13962026/10/07 07:42:57 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13972026/10/07 07:42:57 WARN Failed to register uploaded object key=vjysxxcdkfbaxqgmipwscgkd7rdfp9pg.ls error="server returned 404: 404 page not found\n"13982026/10/07 07:42:57 INFO Signed narinfos id=1 count=213992026/10/07 07:42:57 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14002026/10/07 07:42:57 INFO Signed narinfos id=2 count=214012026/10/07 07:42:57 INFO Uploading 4 narinfos14022026/10/07 07:42:57 WARN Failed to register uploaded object key=wyckaldncfljyylgcq2mrmcvgjdazaj2.narinfo error="server returned 404: 404 page not found\n"14032026/10/07 07:42:57 WARN Failed to register uploaded object key=8ygl8pshdhfh9a9mz3zqczpzgdbvm4f1.narinfo error="server returned 404: 404 page not found\n"14042026/10/07 07:42:57 WARN Failed to register uploaded object key=vjysxxcdkfbaxqgmipwscgkd7rdfp9pg.narinfo error="server returned 404: 404 page not found\n"14052026/10/07 07:42:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14062026/10/07 07:42:57 WARN Failed to register uploaded object key=wyckaldncfljyylgcq2mrmcvgjdazaj2.narinfo error="server returned 404: 404 page not found\n"14072026/10/07 07:42:57 INFO Received push request method=POST path=/api/pushes14082026/10/07 07:42:57 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14092026/10/07 07:42:57 INFO Uploading h9yp9y2klr79hlx0z4yxg32l1b5xvc3p-b (208B)14102026/10/07 07:42:57 INFO Uploading p3avxqw0vjrmmal9hz8p1fijg1061ml0-shared-dep (136B)14112026/10/07 07:42:57 INFO Completed upload id=1 objects=6 duration=10.791503ms14122026/10/07 07:42:57 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14132026/10/07 07:42:57 WARN Failed to register uploaded object key=d9x800xmzcfvx0q9kp3zay722q3zhl32.ls error="server returned 404: 404 page not found\n"14142026/10/07 07:42:57 WARN Failed to register uploaded object key=nar/0grvw9y5z7kk82nbd3mb76x3ddgfqpl8fd82x2s933gjbfkq0jcn.nar.zst error="server returned 404: 404 page not found\n"14152026/10/07 07:42:57 WARN Failed to register uploaded object key=h9yp9y2klr79hlx0z4yxg32l1b5xvc3p.ls error="server returned 404: 404 page not found\n"14162026/10/07 07:42:57 WARN Failed to register uploaded object key=p3avxqw0vjrmmal9hz8p1fijg1061ml0.ls error="server returned 404: 404 page not found\n"14172026/10/07 07:42:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14182026/10/07 07:42:57 INFO Completed upload id=2 objects=6 duration=2.683744ms14192026/10/07 07:42:57 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14202026/10/07 07:42:57 INFO Upload complete. (88ms)14212026/10/07 07:42:57 INFO Signed narinfos id=1 count=314222026/10/07 07:42:57 INFO Uploading 3 narinfos1423=== NAME TestClientFallsBackToClosures1424 client_pushes_test.go:112: Retrieved narinfo from S3:1425 StorePath: /build/TestClientFallsBackToClosures2332601671/001/store/wyckaldncfljyylgcq2mrmcvgjdazaj2-shared-dep1426 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1427 Compression: zstd1428 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821429 NarSize: 1361430 References: 1431 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n14322026/10/07 07:42:57 WARN Failed to register uploaded object key=p3avxqw0vjrmmal9hz8p1fijg1061ml0.narinfo error="server returned 404: 404 page not found\n"1433 client_pushes_test.go:112: Retrieved narinfo from S3:1434 StorePath: /build/TestClientFallsBackToClosures2332601671/001/store/8ygl8pshdhfh9a9mz3zqczpzgdbvm4f1-a14352026/10/07 07:42:57 INFO Received complete push request method=POST path=/api/pushes/1/complete1436 URL: nar/03i4hszxd61ydmr5hq1xrh2mm6dx8s6aq9shd3vp5mk9w4q7m9pv.nar.zst14372026/10/07 07:42:57 WARN Failed to register uploaded object key=d9x800xmzcfvx0q9kp3zay722q3zhl32.narinfo error="server returned 404: 404 page not found\n"1438 Compression: zstd1439 NarHash: sha256:03i4hszxd61ydmr5hq1xrh2mm6dx8s6aq9shd3vp5mk9w4q7m9pv14402026/10/07 07:42:57 WARN Failed to register uploaded object key=h9yp9y2klr79hlx0z4yxg32l1b5xvc3p.narinfo error="server returned 404: 404 page not found\n"1441 NarSize: 2161442 References: /build/TestClientFallsBackToClosures2332601671/001/store/wyckaldncfljyylgcq2mrmcvgjdazaj2-shared-dep1443 CA: text:sha256:018jijpyrh532mr5r4ca3smxs4h3hbd9yvvdifb3w5nil28n19vk1444 client_pushes_test.go:112: Retrieved narinfo from S3:1445 StorePath: /build/TestClientFallsBackToClosures2332601671/001/store/vjysxxcdkfbaxqgmipwscgkd7rdfp9pg-b1446 URL: nar/03i4hszxd61ydmr5hq1xrh2mm6dx8s6aq9shd3vp5mk9w4q7m9pv.nar.zst1447 Compression: zstd1448 NarHash: sha256:03i4hszxd61ydmr5hq1xrh2mm6dx8s6aq9shd3vp5mk9w4q7m9pv1449 NarSize: 2161450 References: /build/TestClientFallsBackToClosures2332601671/001/store/wyckaldncfljyylgcq2mrmcvgjdazaj2-shared-dep1451 CA: text:sha256:018jijpyrh532mr5r4ca3smxs4h3hbd9yvvdifb3w5nil28n19vk14522026/10/07 07:42:57 INFO Completed push id=1 objects=8 duration=7.291899ms14532026/10/07 07:42:57 INFO Upload complete. (65ms)1454=== NAME TestClientPushesUseOnePush1455 client_pushes_test.go:97: Retrieved narinfo from S3:1456 StorePath: /build/TestClientPushesUseOnePush529305089/001/store/p3avxqw0vjrmmal9hz8p1fijg1061ml0-shared-dep1457 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1458 Compression: zstd1459 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821460 NarSize: 1361461 References: 1462 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1463--- PASS: TestClientFallsBackToClosures (0.78s)1464=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1465=== NAME TestClientPushesUseOnePush1466 client_pushes_test.go:97: Retrieved narinfo from S3:1467 StorePath: /build/TestClientPushesUseOnePush529305089/001/store/d9x800xmzcfvx0q9kp3zay722q3zhl32-a1468 URL: nar/0grvw9y5z7kk82nbd3mb76x3ddgfqpl8fd82x2s933gjbfkq0jcn.nar.zst1469 Compression: zstd1470 NarHash: sha256:0grvw9y5z7kk82nbd3mb76x3ddgfqpl8fd82x2s933gjbfkq0jcn1471 NarSize: 2081472 References: /build/TestClientPushesUseOnePush529305089/001/store/p3avxqw0vjrmmal9hz8p1fijg1061ml0-shared-dep1473 CA: text:sha256:0zrbkcwmiqf76hy6fky9q68g90h18435j9scr52ymm912kmjfygc1474 client_pushes_test.go:97: Retrieved narinfo from S3:1475 StorePath: /build/TestClientPushesUseOnePush529305089/001/store/h9yp9y2klr79hlx0z4yxg32l1b5xvc3p-b1476 URL: nar/0grvw9y5z7kk82nbd3mb76x3ddgfqpl8fd82x2s933gjbfkq0jcn.nar.zst1477 Compression: zstd1478 NarHash: sha256:0grvw9y5z7kk82nbd3mb76x3ddgfqpl8fd82x2s933gjbfkq0jcn1479 NarSize: 2081480 References: /build/TestClientPushesUseOnePush529305089/001/store/p3avxqw0vjrmmal9hz8p1fijg1061ml0-shared-dep1481 CA: text:sha256:0zrbkcwmiqf76hy6fky9q68g90h18435j9scr52ymm912kmjfygc1482--- PASS: TestClientPushesUseOnePush (0.75s)1483=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded14842026/10/07 07:42:57 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1485--- PASS: TestReadProxyNarinfo (0.52s)1486=== CONT TestService_ReadAuthMiddleware1487=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1488=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1489=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1490=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1491=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1492=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1493=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1494=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1495=== CONT TestServerTLSConfig1496=== RUN TestServerTLSConfig/no_client_CA1497=== PAUSE TestServerTLSConfig/no_client_CA1498=== RUN TestServerTLSConfig/missing_CA_file1499=== PAUSE TestServerTLSConfig/missing_CA_file1500=== RUN TestServerTLSConfig/not_a_PEM_file1501=== PAUSE TestServerTLSConfig/not_a_PEM_file1502=== CONT TestService_AuthMiddleware_MTLSProxyHeader1503=== NAME TestClientMultipleUploads1504 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads959902030/001/store/d014s6kq8cx2x6yhp9qvkw5bddif75il-test-file-0.txt1505=== NAME TestClientWithDependencies1506 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies2488479825/001/store/6x16hwgqx9zr9yk5h8z6zkfxpvyw70ng-test-script1507--- PASS: TestObjectStatsLargeCommit (1.95s)1508=== CONT TestService_NativeMTLS1509=== NAME TestClientMultipleUploads1510 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads959902030/001/store/rmbjz8qi7ln46i5l53s3pf2lp8xzf6d8-test-file-1.txt1511=== NAME TestClientIntegration1512 client_integration_test.go:286: Created store path: /build/TestClientIntegration2327166980/002/store/v5yav387v4v9k6m4fspjbhl087z5bqcw-test-file.txt1513=== NAME TestClientWithDependencies1514 client_integration_test.go:615: Found 1 dependencies (including self)1515--- PASS: TestService_ReadScope_PublicByDefault (0.30s)1516=== CONT TestGCEndsOnShutdown/before_the_run15172026/10/07 07:42:57 INFO Received push request method=POST path=/api/pushes15182026/10/07 07:42:57 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15192026/10/07 07:42:57 INFO Uploading vm5hlgsfiwd201zl4cfhzmzbrccm8w6n-top (224B)15202026/10/07 07:42:57 INFO Uploading kcksayb9b101flg95kq54kl1z6q3b632-shared-dep (136B)15212026/10/07 07:42:57 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15222026/10/07 07:42:57 WARN Failed to register uploaded object key=kcksayb9b101flg95kq54kl1z6q3b632.ls error="server returned 404: 404 page not found\n"15232026/10/07 07:42:57 WARN Failed to register uploaded object key=vm5hlgsfiwd201zl4cfhzmzbrccm8w6n.ls error="server returned 404: 404 page not found\n"15242026/10/07 07:42:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15252026/10/07 07:42:57 WARN Failed to register uploaded object key=nar/1m6s6wjpnb5n29xfizga5ydfqr7m6aiz3xk23n9i5aa0mg7iw0vw.nar.zst error="server returned 404: 404 page not found\n"15262026/10/07 07:42:57 INFO Signed narinfos id=1 count=215272026/10/07 07:42:57 INFO Uploading 2 narinfos15282026/10/07 07:42:57 INFO Received complete push request method=POST path=/api/pushes/1/complete15292026/10/07 07:42:57 WARN Failed to register uploaded object key=kcksayb9b101flg95kq54kl1z6q3b632.narinfo error="server returned 404: 404 page not found\n"15302026/10/07 07:42:57 WARN Failed to register uploaded object key=vm5hlgsfiwd201zl4cfhzmzbrccm8w6n.narinfo error="server returned 404: 404 page not found\n"1531=== NAME TestClientMultipleUploads1532 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads959902030/001/store/l348xdmkb92p9rs985ygy48dnh1ghgvd-test-file-2.txt15332026/10/07 07:42:57 INFO Received uploads request method=POST path=/api/pending_closures15342026/10/07 07:42:57 INFO Completed push id=1 objects=6 duration=10.703483ms15352026/10/07 07:42:57 INFO Upload complete. (74ms)1536=== NAME TestClientSharedPathCommittedMidPush1537 client_integration_test.go:680: Retrieved narinfo from S3:1538 StorePath: /build/TestClientSharedPathCommittedMidPush687039958/001/store/kcksayb9b101flg95kq54kl1z6q3b632-shared-dep1539 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1540 Compression: zstd1541 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821542 NarSize: 1361543 References: 1544 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1545 client_integration_test.go:680: Retrieved narinfo from S3:1546 StorePath: /build/TestClientSharedPathCommittedMidPush687039958/001/store/vm5hlgsfiwd201zl4cfhzmzbrccm8w6n-top1547 URL: nar/1m6s6wjpnb5n29xfizga5ydfqr7m6aiz3xk23n9i5aa0mg7iw0vw.nar.zst1548 Compression: zstd1549 NarHash: sha256:1m6s6wjpnb5n29xfizga5ydfqr7m6aiz3xk23n9i5aa0mg7iw0vw1550 NarSize: 2241551 References: /build/TestClientSharedPathCommittedMidPush687039958/001/store/kcksayb9b101flg95kq54kl1z6q3b632-shared-dep1552 CA: text:sha256:077p3vchr3pkiivdl71c632x58pcgrpw7s6ly66za5r33w7fn7qa1553--- PASS: TestClientSharedPathCommittedMidPush (0.61s)1554=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark15552026/10/07 07:42:57 INFO Received push request method=POST path=/api/pushes15562026/10/07 07:42:57 INFO Received complete push request method=POST path=/api/pushes/1/complete1557=== NAME TestClientCADerivations1558 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations1732082799/001/store/as0vkrznmkxg048zcglwjspgzqrljkip-ca-test15592026/10/07 07:42:57 INFO Received push request method=POST path=/api/pushes15602026/10/07 07:42:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15612026/10/07 07:42:57 INFO Uploading 6x16hwgqx9zr9yk5h8z6zkfxpvyw70ng-test-script (136B)15622026/10/07 07:42:57 INFO Completed push id=1 objects=4 duration=11.451294ms15632026/10/07 07:42:57 INFO Received push request method=POST path=/api/pushes15642026/10/07 07:42:57 WARN Failed to register uploaded object key=log/vvny7sjvs22vi4052pgsg30v3agrjxyn-test-script.drv error="server returned 404: 404 page not found\n"15652026/10/07 07:42:57 WARN Failed to register uploaded object key=6x16hwgqx9zr9yk5h8z6zkfxpvyw70ng.ls error="server returned 404: 404 page not found\n"15662026/10/07 07:42:57 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15672026/10/07 07:42:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15682026/10/07 07:42:57 INFO Signed narinfos id=1 count=115692026/10/07 07:42:57 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15702026/10/07 07:42:57 INFO Uploading 1 narinfos15712026/10/07 07:42:57 INFO Completed upload id=2 objects=2 duration=2.081703ms15722026/10/07 07:42:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15732026/10/07 07:42:57 INFO Uploading v5yav387v4v9k6m4fspjbhl087z5bqcw-test-file.txt (152B)15742026/10/07 07:42:57 INFO Received complete push request method=POST path=/api/pushes/1/complete15752026/10/07 07:42:57 WARN Failed to register uploaded object key=6x16hwgqx9zr9yk5h8z6zkfxpvyw70ng.narinfo error="server returned 404: 404 page not found\n"1576=== RUN TestService_RequireScope_OIDC/builder_may_write1577=== PAUSE TestService_RequireScope_OIDC/builder_may_write1578=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1579=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1580=== RUN TestService_RequireScope_OIDC/ops_may_admin1581=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1582=== RUN TestService_RequireScope_OIDC/ops_may_not_write1583=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1584=== RUN TestService_RequireScope_OIDC/reader_may_not_write1585=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1586=== RUN TestService_RequireScope_OIDC/static_token_may_admin1587=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1588=== RUN TestService_RequireScope_OIDC/static_token_may_write1589=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1590=== RUN TestService_RequireScope_OIDC/reader_may_read1591=== PAUSE TestService_RequireScope_OIDC/reader_may_read1592=== RUN TestService_RequireScope_OIDC/writer_implies_read1593=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1594=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1595=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1596=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1597=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1598=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1599=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1600=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1601=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1602=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1603=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1604=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1605--- PASS: TestMetricsCommit (0.33s)1606=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows16072026/10/07 07:42:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16082026/10/07 07:42:57 INFO Signed narinfos id=1 count=116092026/10/07 07:42:57 WARN Failed to register uploaded object key=v5yav387v4v9k6m4fspjbhl087z5bqcw.ls error="server returned 404: 404 page not found\n"16102026/10/07 07:42:57 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16112026/10/07 07:42:57 INFO Uploading 1 narinfos16122026/10/07 07:42:57 INFO Received push request method=POST path=/api/pushes16132026/10/07 07:42:57 INFO Received complete push request method=POST path=/api/pushes/1/complete16142026/10/07 07:42:57 WARN Failed to register uploaded object key=v5yav387v4v9k6m4fspjbhl087z5bqcw.narinfo error="server returned 404: 404 page not found\n"16152026/10/07 07:42:57 INFO Completed push id=1 objects=4 duration=10.045333ms16162026/10/07 07:42:57 INFO Upload complete. (70ms)1617=== NAME TestClientCADerivations1618 client_ca_test.go:139: Found 1 dependencies (including self)1619=== NAME TestClientWithDependencies1620 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies2488479825/001/store) requires matching store prefix16212026/10/07 07:42:57 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16222026/10/07 07:42:57 INFO Uploading d014s6kq8cx2x6yhp9qvkw5bddif75il-test-file-0.txt (160B)16232026/10/07 07:42:57 INFO Uploading rmbjz8qi7ln46i5l53s3pf2lp8xzf6d8-test-file-1.txt (160B)16242026/10/07 07:42:57 INFO Uploading l348xdmkb92p9rs985ygy48dnh1ghgvd-test-file-2.txt (160B)16252026/10/07 07:42:57 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16262026/10/07 07:42:57 INFO Completed push id=1 objects=3 duration=9.744393ms16272026/10/07 07:42:57 INFO Upload complete. (78ms)16282026/10/07 07:42:57 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16292026/10/07 07:42:57 WARN Failed to register uploaded object key=d014s6kq8cx2x6yhp9qvkw5bddif75il.ls error="server returned 404: 404 page not found\n"16302026/10/07 07:42:57 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16312026/10/07 07:42:57 WARN Failed to register uploaded object key=rmbjz8qi7ln46i5l53s3pf2lp8xzf6d8.ls error="server returned 404: 404 page not found\n"16322026/10/07 07:42:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16332026/10/07 07:42:57 WARN Failed to register uploaded object key=l348xdmkb92p9rs985ygy48dnh1ghgvd.ls error="server returned 404: 404 page not found\n"16342026/10/07 07:42:57 INFO Signed narinfos id=1 count=316352026/10/07 07:42:57 INFO Uploading 3 narinfos1636--- PASS: TestClientWithDependencies (0.66s)1637=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1638--- PASS: TestObjectStatsTrigger (0.30s)1639=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16402026/10/07 07:42:57 INFO Received uploads request method=POST path=/16412026/10/07 07:42:57 WARN Failed to register uploaded object key=d014s6kq8cx2x6yhp9qvkw5bddif75il.narinfo error="server returned 404: 404 page not found\n"16422026/10/07 07:42:57 WARN Failed to register uploaded object key=l348xdmkb92p9rs985ygy48dnh1ghgvd.narinfo error="server returned 404: 404 page not found\n"16432026/10/07 07:42:57 INFO Received complete push request method=POST path=/api/pushes/1/complete16442026/10/07 07:42:57 WARN Failed to register uploaded object key=rmbjz8qi7ln46i5l53s3pf2lp8xzf6d8.narinfo error="server returned 404: 404 page not found\n"16452026/10/07 07:42:57 INFO Received uploads request method=POST path=/api/pending_closures16462026/10/07 07:42:57 INFO Completed push id=1 objects=9 duration=13.341627ms16472026/10/07 07:42:57 INFO Upload complete. (72ms)1648=== NAME TestClientMultipleUploads1649 client_integration_test.go:369: Uploaded 3 paths in 108.499907ms16502026/10/07 07:42:57 INFO Received uploads request method=POST path=/api/pending_closures16512026/10/07 07:42:57 INFO Received cleanup request method=DELETE path=/api/pending_closures1652--- PASS: TestClientMultipleUploads (0.57s)1653=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16542026/10/07 07:42:57 INFO Received request for more parts method=POST path=/16552026/10/07 07:42:57 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket81/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""16562026/10/07 07:42:57 INFO Aborted multipart uploads count=0 kept=116572026/10/07 07:42:57 INFO Received cleanup request method=DELETE path=/api/pending_closures16582026/10/07 07:42:57 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16592026/10/07 07:42:57 WARN mTLS auth: bound subjects configured but subject DN unavailable16602026/10/07 07:42:57 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1661--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.27s)1662=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16632026/10/07 07:42:57 INFO Received complete multipart upload request method=POST path=/16642026/10/07 07:42:57 INFO Received cleanup request method=DELETE path=/api/pending_closures16652026/10/07 07:42:57 INFO All 1 paths already cached16662026/10/07 07:42:57 INFO Aborted multipart uploads count=1 kept=01667=== NAME TestClientIntegration1668 client_integration_test.go:312: Retrieved narinfo from S3:1669 StorePath: /build/TestClientIntegration2327166980/002/store/v5yav387v4v9k6m4fspjbhl087z5bqcw-test-file.txt1670 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1671 Compression: zstd1672 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11673 NarSize: 1521674 References: 1675 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11676--- PASS: TestMultipartCleanup (0.41s)1677=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1678=== NAME TestClientIntegration16792026/10/07 07:42:57 INFO Received uploads request method=POST path=/1680 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1681=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1682=== NAME TestClientIntegration16832026/10/07 07:42:57 INFO Received complete multipart upload request method=POST path=/1684 client_integration_test.go:313: Decompressed .ls content (64 bytes):1685 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1686 client_integration_test.go:316: Testing garbage collection...1687=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16882026/10/07 07:42:57 INFO Received request for more parts method=POST path=/1689=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16902026/10/07 07:42:57 INFO Received uploads request method=POST path=/1691=== CONT TestIsValidUploadKey/narinfo1692--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1693 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1694 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1695 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1696 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1697=== CONT TestIsValidUploadKey/realisation_plus_in_output1698=== CONT TestIsValidUploadKey/unknown_type1699=== CONT TestIsValidUploadKey/empty_key1700=== CONT TestIsValidUploadKey/absolute1701=== CONT TestIsValidUploadKey/traversal_nar1702=== CONT TestIsValidUploadKey/traversal1703=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1704=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1705=== CONT TestIsValidUploadKey/build_log_home-manager_file1706=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1707=== CONT TestIsValidUploadKey/realisation1708=== CONT TestIsValidUploadKey/index.html1709=== CONT TestIsValidUploadKey/build_log_equals1710=== CONT TestIsValidUploadKey/nix-cache-info1711=== CONT TestIsValidUploadKey/build_log_question_mark1712=== CONT TestIsValidUploadKey/build_log_plus_in_name1713=== CONT TestIsValidUploadKey/nar_plain1714=== CONT TestIsValidUploadKey/build_log1715=== CONT TestIsValidUploadKey/nar_xz1716=== CONT TestIsValidUploadKey/nar_zst1717=== CONT TestIsValidUploadKey/listing1718--- PASS: TestIsValidUploadKey (0.00s)1719 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1720 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1721 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1722 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1723 --- PASS: TestIsValidUploadKey/absolute (0.00s)1724 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1725 --- PASS: TestIsValidUploadKey/traversal (0.00s)1726 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1727 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1728 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1729 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1730 --- PASS: TestIsValidUploadKey/realisation (0.00s)1731 --- PASS: TestIsValidUploadKey/index.html (0.00s)1732 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1733 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1734 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1735 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1736 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1737 --- PASS: TestIsValidUploadKey/build_log (0.00s)1738 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1739 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1740 --- PASS: TestIsValidUploadKey/listing (0.00s)1741=== CONT TestPendingClosureWriteTimeout/empty1742=== CONT TestPendingClosureWriteTimeout/670k_objects1743=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline17442026/10/07 07:42:57 INFO Received uploads request method=POST path=/api/pending_closures1745--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.30s)17462026/10/07 07:42:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures1747=== CONT TestPendingClosureWriteTimeout/400_objects1748=== CONT TestProxyWriteTimeout/narinfo1749=== CONT TestProxyWriteTimeout/10_GiB_nar1750=== CONT TestProxyWriteTimeout/unknown_size1751=== CONT TestProxyWriteTimeout/1_GiB_nar17522026/10/07 07:42:57 INFO Garbage collection started1753=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1754--- PASS: TestProxyWriteTimeout (0.00s)1755 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1756 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1757 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1758 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1759--- PASS: TestService_ReadAuthMiddleware (0.29s)1760=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh17612026/10/07 07:42:57 INFO Aborted multipart uploads count=0 kept=01762=== CONT TestPush_RejectsBadRequests/root_not_in_objects17632026/10/07 07:42:57 INFO Received push request method=POST path=/api/pushes1764=== CONT TestPush_RejectsBadRequests/no_objects17652026/10/07 07:42:57 INFO Received push request method=POST path=/api/pushes1766=== CONT TestPush_RejectsBadRequests/no_roots17672026/10/07 07:42:57 INFO Received push request method=POST path=/api/pushes1768=== CONT TestPush_RejectsBadRequests/bad_root17692026/10/07 07:42:57 INFO Received push request method=POST path=/api/pushes1770=== CONT TestParseSingleRange/none1771=== CONT TestParseSingleRange/open-ended1772=== CONT TestParseSingleRange/start_far_past_EOF1773=== CONT TestParseSingleRange/start_past_EOF1774=== CONT TestParseSingleRange/single_byte1775=== CONT TestParseSingleRange/suffix_exceeds_size1776=== CONT TestParseSingleRange/suffix1777=== CONT TestParseSingleRange/end_clamped_to_size1778=== CONT TestParseSingleRange/malformed_both_empty1779=== CONT TestParseSingleRange/closed1780=== CONT TestParseSingleRange/malformed_end_before_start1781=== CONT TestParseSingleRange/malformed_no_dash1782=== CONT TestParseSingleRange/unknown_unit1783=== CONT TestParseSingleRange/multi-range_ignored1784=== CONT TestResolveDBConnectionString/flag_wins1785=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1786=== CONT TestResolveDBConnectionString/nothing_configured1787=== CONT TestResolveDBConnectionString/missing_file_is_an_error1788--- PASS: TestPush_RejectsBadRequests (0.69s)1789 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1790 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1791 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1792 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1793=== CONT TestResolveDBConnectionString/file_when_flag_empty1794=== CONT TestIsValidCachePath/narinfo1795=== CONT TestIsValidCachePath/index.html1796=== CONT TestIsValidCachePath/short_hash1797=== CONT TestIsValidCachePath/wrong_extension1798=== CONT TestIsValidCachePath/leading_slash1799=== CONT TestIsValidCachePath/empty1800=== CONT TestIsValidCachePath/random_path1801=== CONT TestIsValidCachePath/invalid_char_u1802=== CONT TestIsValidCachePath/invalid_char_e1803=== CONT TestIsValidCachePath/traversal_in_middle1804=== CONT TestIsValidCachePath/traversal_parent1805=== CONT TestIsValidCachePath/nar_uncompressed18062026/10/07 07:42:57 WARN Force mode enabled - objects will be deleted immediately without grace period1807=== CONT TestIsValidCachePath/nix-cache-info1808--- PASS: TestParseSingleRange (0.00s)1809 --- PASS: TestParseSingleRange/none (0.00s)1810 --- PASS: TestParseSingleRange/open-ended (0.00s)1811 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1812 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1813 --- PASS: TestParseSingleRange/single_byte (0.00s)1814 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1815 --- PASS: TestParseSingleRange/suffix (0.00s)1816 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1817 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1818 --- PASS: TestParseSingleRange/closed (0.00s)1819 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1820 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1821 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1822 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1823=== CONT TestIsValidCachePath/realisation1824=== CONT TestIsValidCachePath/log1825=== CONT TestIsValidCachePath/ls1826=== CONT TestIsValidCachePath/nar_xz1827=== CONT TestIsValidCachePath/nar_bz21828=== CONT TestIsValidCachePath/nar_zst1829=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1830=== CONT TestCacheConfigHandler/full_config,_no_issuer1831--- PASS: TestIsValidCachePath (0.00s)1832 --- PASS: TestIsValidCachePath/narinfo (0.00s)1833 --- PASS: TestIsValidCachePath/index.html (0.00s)1834 --- PASS: TestIsValidCachePath/short_hash (0.00s)1835 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1836 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1837 --- PASS: TestIsValidCachePath/empty (0.00s)1838 --- PASS: TestIsValidCachePath/random_path (0.00s)1839 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1840 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1841 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1842 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1843 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1844 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1845 --- PASS: TestIsValidCachePath/realisation (0.00s)1846 --- PASS: TestIsValidCachePath/log (0.00s)1847 --- PASS: TestIsValidCachePath/ls (0.00s)1848 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1849 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1850 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1851 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1852--- PASS: TestResolveDBConnectionString (0.00s)1853 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1854 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1855 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1856 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1857 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1858=== CONT TestCacheConfigHandler/no_signing_keys1859=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1860=== CONT TestCacheConfigHandler/no_cache_url_configured1861--- PASS: TestCacheConfigHandler (0.00s)1862 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1863 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1864 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1865 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1866=== CONT TestClientErrorHandling/InvalidStorePath1867=== CONT TestClientErrorHandling/ServerNotAvailable18682026/10/07 07:42:57 INFO Received push request method=POST path=/api/pushes1869--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.30s)1870=== CONT TestClientErrorHandling/InvalidAuthToken18712026/10/07 07:42:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18722026/10/07 07:42:57 INFO Uploading as0vkrznmkxg048zcglwjspgzqrljkip-ca-test (144B)18732026/10/07 07:42:57 WARN Failed to register uploaded object key=as0vkrznmkxg048zcglwjspgzqrljkip.ls error="server returned 404: 404 page not found\n"18742026/10/07 07:42:57 WARN Failed to register uploaded object key=log/4lp2pcnakx2c9dvqrvfkcn5v3jiqayb3-ca-test.drv error="server returned 404: 404 page not found\n"18752026/10/07 07:42:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18762026/10/07 07:42:57 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=018772026/10/07 07:42:57 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18782026/10/07 07:42:57 INFO Signed narinfos id=1 count=118792026/10/07 07:42:57 INFO Uploading 1 narinfos18802026/10/07 07:42:57 INFO Received complete push request method=POST path=/api/pushes/1/complete18812026/10/07 07:42:57 WARN Failed to register uploaded object key=as0vkrznmkxg048zcglwjspgzqrljkip.narinfo error="server returned 404: 404 page not found\n"18822026/10/07 07:42:57 INFO Vacuumed table table=pending_closures18832026/10/07 07:42:57 INFO Completed push id=1 objects=4 duration=7.83356ms18842026/10/07 07:42:57 INFO Upload complete. (99ms)18852026/10/07 07:42:57 INFO Vacuumed table table=pending_objects18862026/10/07 07:42:57 INFO Vacuumed table table=multipart_uploads1887=== NAME TestClientCADerivations1888 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations1732082799/001/store/as0vkrznmkxg048zcglwjspgzqrljkip-ca-test1889 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1890 Compression: zstd1891 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1892 NarSize: 1441893 References: 1894 Deriver: /build/TestClientCADerivations1732082799/001/store/4lp2pcnakx2c9dvqrvfkcn5v3jiqayb3-ca-test.drv1895 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1896 client_ca_test.go:185: Checking for realisation files in S3...18972026/10/07 07:42:57 INFO Vacuumed table table=closures1898 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1899 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache19002026/10/07 07:42:57 INFO Vacuumed table table=objects19012026/10/07 07:42:57 WARN mTLS auth: subject not in bound subjects subject="CN=reader"19022026/10/07 07:42:57 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1903--- PASS: TestService_NativeMTLS (0.28s)1904=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1905=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19062026/10/07 07:42:57 WARN Authentication failed token_preview=not-a-valid-jwt token_length=15 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]1907=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1908=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19092026/10/07 07:42:57 WARN Authentication failed token_preview=eyJhbGciOi...wDHN1uIXbQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1910=== CONT TestServerTLSConfig/no_client_CA1911=== CONT TestServerTLSConfig/not_a_PEM_file1912--- PASS: TestService_AuthMiddleware_OIDC (0.43s)1913 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1914 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1915 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1916 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1917=== CONT TestServerTLSConfig/missing_CA_file1918--- PASS: TestServerTLSConfig (0.00s)1919 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1920 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1921 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1922=== CONT TestService_RequireScope_OIDC/builder_may_write1923=== CONT TestService_RequireScope_OIDC/reader_may_read1924=== CONT TestService_RequireScope_OIDC/static_token_may_write1925=== CONT TestService_RequireScope_OIDC/static_token_may_admin1926=== CONT TestService_RequireScope_OIDC/reader_may_not_write1927=== CONT TestService_RequireScope_OIDC/ops_may_not_write1928=== CONT TestService_RequireScope_OIDC/ops_may_admin1929=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1930=== CONT TestService_RequireScope_OIDC/writer_implies_read1931=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19322026/10/07 07:42:57 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]1933=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1934=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1935=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1936=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1937--- PASS: TestService_RequireScope_OIDC (0.37s)1938 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1939 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1940 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1941 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1942 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1943 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1944 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1945 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1946 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1947 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1948 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1949 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1950 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1951 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)19522026/10/07 07:42:57 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19532026/10/07 07:42:57 INFO Aborted multipart uploads count=0 kept=019542026/10/07 07:42:57 WARN Force mode enabled - objects will be deleted immediately without grace period19552026/10/07 07:42:57 INFO Aborted multipart uploads count=0 kept=019562026/10/07 07:42:57 WARN Force mode enabled - objects will be deleted immediately without grace period19572026/10/07 07:42:57 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:46505/bucket93/?delete=\": context canceled"1958--- PASS: TestGCEndsOnShutdown (0.00s)1959 --- PASS: TestGCEndsOnShutdown/before_the_run (0.28s)1960 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.29s)1961 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.25s)19622026/10/07 07:42:57 INFO Received uploads request method=POST path=/api/pending_closures19632026/10/07 07:42:57 INFO Aborted multipart uploads count=0 kept=019642026/10/07 07:42:57 WARN Force mode enabled - objects will be deleted immediately without grace period1965=== NAME TestClientCADerivations1966 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1967 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1968 error: binary cache 's3://bucket79?endpoint=http://localhost:46505®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations1732082799/001/store'1969 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 119702026/10/07 07:42:57 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=019712026/10/07 07:42:57 INFO Vacuumed table table=pending_closures19722026/10/07 07:42:57 INFO Vacuumed table table=pending_objects19732026/10/07 07:42:57 INFO Vacuumed table table=multipart_uploads1974--- PASS: TestClientCADerivations (0.73s)19752026/10/07 07:42:57 INFO Vacuumed table table=closures19762026/10/07 07:42:57 INFO Received uploads request method=POST path=/api/pending_closures19772026/10/07 07:42:57 INFO Vacuumed table table=objects19782026/10/07 07:42:57 INFO Aborted multipart uploads count=0 kept=019792026/10/07 07:42:57 INFO Received uploads request method=POST path=/api/pending_closures19802026/10/07 07:42:57 WARN Force mode enabled - objects will be deleted immediately without grace period19812026/10/07 07:42:57 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=019822026/10/07 07:42:57 INFO Vacuumed table table=pending_closures19832026/10/07 07:42:57 INFO Vacuumed table table=pending_objects19842026/10/07 07:42:57 INFO Vacuumed table table=multipart_uploads19852026/10/07 07:42:57 INFO Vacuumed table table=closures19862026/10/07 07:42:57 INFO Vacuumed table table=objects19872026/10/07 07:42:57 INFO lead: released remote=192.0.2.1:12341988--- PASS: TestLeadEndsOnShutdown (1.96s)19892026/10/07 07:42:57 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=195.162671ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1990--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)1991 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.42s)1992 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.41s)19932026/10/07 07:42:58 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19942026/10/07 07:42:58 INFO lead: released remote=192.0.2.1:123419952026/10/07 07:42:58 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"19962026/10/07 07:42:58 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=407.147395ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19972026/10/07 07:42:58 INFO lead: acquired remote=192.0.2.1:12341998--- PASS: TestDeleteClosuresRacingPins (1.70s)1999=== NAME TestOrphanedObjectsGCStressTest2000 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2001 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2002--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)2003 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)2004 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)2005 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.79s)2006--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2007 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.83s)2008 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.86s)2009=== NAME TestOrphanedObjectsGCStressTest2010 orphaned_objects_gc_test.go:503: Stress test completed successfully:2011 orphaned_objects_gc_test.go:504: - Active objects preserved: 202012 orphaned_objects_gc_test.go:505: - Objects deleted: 2102013 orphaned_objects_gc_test.go:506: - Total GC'd: 2102014--- PASS: TestOrphanedObjectsGCStressTest (2.76s)20152026/10/07 07:42:58 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=774.530891ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2016--- PASS: TestPendingClosureWriteTimeout (0.00s)2017 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2018 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2019 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2020 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.33s)20212026/10/07 07:42:59 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020222026/10/07 07:42:59 INFO Received create pin request method=POST path=/api/pins/myapp20232026/10/07 07:42:59 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3104024167/001/store/c5zg1790qpgrs3y7smf94rj4fx36d8ak-pinned-file.txt narinfo_key=c5zg1790qpgrs3y7smf94rj4fx36d8ak.narinfo20242026/10/07 07:42:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures20252026/10/07 07:42:59 INFO Garbage collection started20262026/10/07 07:42:59 INFO Aborted multipart uploads count=0 kept=020272026/10/07 07:42:59 WARN Force mode enabled - objects will be deleted immediately without grace period20282026/10/07 07:42:59 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020292026/10/07 07:42:59 INFO Vacuumed table table=pending_closures20302026/10/07 07:42:59 INFO Vacuumed table table=pending_objects20312026/10/07 07:42:59 INFO Vacuumed table table=multipart_uploads20322026/10/07 07:42:59 INFO Vacuumed table table=closures20332026/10/07 07:42:59 INFO Vacuumed table table=objects20342026/10/07 07:42:59 INFO lead: released remote=192.0.2.1:12342035--- PASS: TestLeadElectsOneAndHandsOver (3.06s)20362026/10/07 07:42:59 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.463901129s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20372026/10/07 07:42:59 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02038=== NAME TestClientIntegration2039 client_integration_test.go:323: Objects in database after GC:2040 client_integration_test.go:323: Successfully deleted all objects with GC --force2041--- PASS: TestClientIntegration (2.58s)20422026/10/07 07:43:00 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20432026/10/07 07:43:00 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=214.559723ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2044=== NAME TestPinProtectsFromGC2045 client_integration_test.go:840: Pin successfully protected closure from garbage collection2046--- PASS: TestPinProtectsFromGC (5.15s)2047--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.76s)20482026/10/07 07:43:01 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=374.108025ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2049--- PASS: TestConnectWaitsForAPeerMigration (5.25s)20502026/10/07 07:43:01 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=844.441801ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20512026/10/07 07:43:02 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.448914708s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20522026/10/07 07:43:02 WARN Rate limiter enabled after throttle name=s3-test rate=520532026/10/07 07:43:02 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2054=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2055 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102056 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002057--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (7.76s)20582026/10/07 07:43:03 INFO Aborted multipart uploads count=1 kept=020592026/10/07 07:43:03 INFO Received cleanup request method=DELETE path=/api/pending_closures20602026/10/07 07:43:03 INFO Aborted multipart uploads count=1 kept=02061--- PASS: TestPendingCleanupUsesOneCutoff (6.33s)20622026/10/07 07:43:03 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"20632026/10/07 07:43:03 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20642026/10/07 07:43:03 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=202.986559ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20652026/10/07 07:43:04 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=377.76948ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20662026/10/07 07:43:04 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=783.475844ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20672026/10/07 07:43:05 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.631621053s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20682026/10/07 07:43:06 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20692026/10/07 07:43:07 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=202.598026ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20702026/10/07 07:43:07 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=389.238817ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20712026/10/07 07:43:07 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=824.221531ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures20722026/10/07 07:43:08 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.633768781s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2073--- PASS: TestClientErrorHandling (0.00s)2074 --- PASS: TestClientErrorHandling/InvalidStorePath (0.42s)2075 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.46s)2076 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.44s)2077PASS2078{"timestamp":"2026-10-07T07:43:10.117184103Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:33910","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(390)"}20792026-10-07 07:43:10.511 UTC [128] LOG: received smart shutdown request20802026-10-07 07:43:10.515 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 120812026-10-07 07:43:10.528 UTC [133] LOG: shutting down20822026-10-07 07:43:10.528 UTC [133] LOG: checkpoint starting: shutdown immediate20832026-10-07 07:43:11.719 UTC [133] LOG: checkpoint complete: wrote 10869 buffers (66.3%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.266 s, sync=0.870 s, total=1.191 s; sync files=34046, longest=0.050 s, average=0.001 s; distance=531600 kB, estimate=531600 kB; lsn=0/21E89E18, redo lsn=0/21E89E1820842026-10-07 07:43:11.805 UTC [128] LOG: database system is shut down2085Running OIDC tests...2086=== RUN TestAudienceForIssuer2087=== PAUSE TestAudienceForIssuer2088=== RUN TestGlobMatch2089=== PAUSE TestGlobMatch2090=== RUN TestValidateToken_ValidToken2091=== PAUSE TestValidateToken_ValidToken2092=== RUN TestValidateToken_WrongAudience2093=== PAUSE TestValidateToken_WrongAudience2094=== RUN TestValidateToken_Expired2095=== PAUSE TestValidateToken_Expired2096=== RUN TestValidateToken_BoundClaimsMismatch2097=== PAUSE TestValidateToken_BoundClaimsMismatch2098=== RUN TestValidateToken_BoundSubjectMismatch2099=== PAUSE TestValidateToken_BoundSubjectMismatch2100=== RUN TestValidateToken_MultipleProviders2101=== PAUSE TestValidateToken_MultipleProviders2102=== RUN TestValidateToken_NoMatchingProvider2103=== PAUSE TestValidateToken_NoMatchingProvider2104=== RUN TestValidateToken_KubernetesServiceAccount2105=== PAUSE TestValidateToken_KubernetesServiceAccount2106=== RUN TestNewValidator_KubernetesRequiresCA2107=== PAUSE TestNewValidator_KubernetesRequiresCA2108=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2109=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2110=== RUN TestPins_ReservedForMatchingRule2111=== PAUSE TestPins_ReservedForMatchingRule2112=== RUN TestPins_TopLevelShorthand2113=== PAUSE TestPins_TopLevelShorthand2114=== RUN TestPins_ConfigValidation2115=== PAUSE TestPins_ConfigValidation2116=== RUN TestScopes_LegacyProviderDefaultsToWrite2117=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2118=== RUN TestScopes_Rules2119=== PAUSE TestScopes_Rules2120=== RUN TestScopes_ConfigValidation2121=== PAUSE TestScopes_ConfigValidation2122=== CONT TestAudienceForIssuer2123=== CONT TestValidateToken_KubernetesServiceAccount2124--- PASS: TestAudienceForIssuer (0.00s)2125=== CONT TestScopes_ConfigValidation2126=== CONT TestValidateToken_BoundClaimsMismatch2127=== CONT TestValidateToken_Expired2128=== CONT TestValidateToken_WrongAudience2129--- PASS: TestScopes_ConfigValidation (0.00s)2130=== CONT TestValidateToken_ValidToken2131=== CONT TestGlobMatch2132=== RUN TestGlobMatch/foo_foo2133=== PAUSE TestGlobMatch/foo_foo2134=== RUN TestGlobMatch/foo_bar2135=== CONT TestPins_ConfigValidation2136=== CONT TestPins_ReservedForMatchingRule2137=== CONT TestPins_TopLevelShorthand2138=== CONT TestValidateToken_MultipleProviders2139=== CONT TestValidateToken_NoMatchingProvider2140=== CONT TestScopes_Rules2141--- PASS: TestPins_ConfigValidation (0.00s)2142=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2143=== CONT TestScopes_LegacyProviderDefaultsToWrite2144=== CONT TestValidateToken_BoundSubjectMismatch2145=== CONT TestNewValidator_KubernetesRequiresCA2146=== PAUSE TestGlobMatch/foo_bar2147=== RUN TestGlobMatch/*_2148=== PAUSE TestGlobMatch/*_2149=== RUN TestGlobMatch/*_anything2150=== PAUSE TestGlobMatch/*_anything2151=== RUN TestGlobMatch/foo*_foo2152=== PAUSE TestGlobMatch/foo*_foo2153=== RUN TestGlobMatch/foo*_foobar2154=== PAUSE TestGlobMatch/foo*_foobar2155=== RUN TestGlobMatch/foo*_bar2156=== PAUSE TestGlobMatch/foo*_bar2157=== RUN TestGlobMatch/*bar_bar2158=== PAUSE TestGlobMatch/*bar_bar2159=== RUN TestGlobMatch/*bar_foobar2160=== PAUSE TestGlobMatch/*bar_foobar2161=== RUN TestGlobMatch/*bar_foo2162=== PAUSE TestGlobMatch/*bar_foo2163=== RUN TestGlobMatch/foo*bar_foobar2164=== PAUSE TestGlobMatch/foo*bar_foobar2165=== RUN TestGlobMatch/foo*bar_foo123bar2166=== PAUSE TestGlobMatch/foo*bar_foo123bar2167=== RUN TestGlobMatch/foo*bar_foobarbaz2168=== PAUSE TestGlobMatch/foo*bar_foobarbaz2169=== RUN TestGlobMatch/*/*_foo/bar2170=== PAUSE TestGlobMatch/*/*_foo/bar2171=== RUN TestGlobMatch/*/*_foo2172=== PAUSE TestGlobMatch/*/*_foo2173=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2174=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2175=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02176=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02177=== RUN TestGlobMatch/refs/*/main_refs/heads/main2178=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2179=== RUN TestGlobMatch/fo?_foo2180=== PAUSE TestGlobMatch/fo?_foo2181=== RUN TestGlobMatch/fo?_fo2182=== PAUSE TestGlobMatch/fo?_fo2183=== RUN TestGlobMatch/fo?_fooo2184=== PAUSE TestGlobMatch/fo?_fooo2185=== RUN TestGlobMatch/?oo_foo2186=== PAUSE TestGlobMatch/?oo_foo2187=== RUN TestGlobMatch/?oo_boo2188=== PAUSE TestGlobMatch/?oo_boo2189=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2190=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2191=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2192=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2193=== CONT TestGlobMatch/foo_foo2194=== CONT TestGlobMatch/foo*bar_foobarbaz2195=== CONT TestGlobMatch/foo*bar_foo123bar2196=== CONT TestGlobMatch/foo*bar_foobar2197=== CONT TestGlobMatch/*bar_foo2198=== CONT TestGlobMatch/*bar_foobar2199=== CONT TestGlobMatch/*bar_bar2200=== CONT TestGlobMatch/foo*_bar2201=== CONT TestGlobMatch/foo*_foobar2202=== CONT TestGlobMatch/foo*_foo2203=== CONT TestGlobMatch/*_anything2204=== CONT TestGlobMatch/*_2205=== CONT TestGlobMatch/foo_bar2206=== CONT TestGlobMatch/fo?_fo2207=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2208=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2209=== CONT TestGlobMatch/?oo_boo2210=== CONT TestGlobMatch/?oo_foo2211=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2212=== CONT TestGlobMatch/*/*_foo/bar2213=== CONT TestGlobMatch/fo?_foo2214=== CONT TestGlobMatch/refs/*/main_refs/heads/main2215=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02216=== CONT TestGlobMatch/fo?_fooo2217=== CONT TestGlobMatch/*/*_foo2218--- PASS: TestGlobMatch (0.01s)2219 --- PASS: TestGlobMatch/foo_foo (0.00s)2220 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2221 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2222 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2223 --- PASS: TestGlobMatch/*bar_foo (0.00s)2224 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2225 --- PASS: TestGlobMatch/*bar_bar (0.00s)2226 --- PASS: TestGlobMatch/foo*_bar (0.00s)2227 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2228 --- PASS: TestGlobMatch/foo*_foo (0.00s)2229 --- PASS: TestGlobMatch/*_anything (0.00s)2230 --- PASS: TestGlobMatch/*_ (0.00s)2231 --- PASS: TestGlobMatch/foo_bar (0.00s)2232 --- PASS: TestGlobMatch/fo?_fo (0.00s)2233 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2234 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2235 --- PASS: TestGlobMatch/?oo_boo (0.00s)2236 --- PASS: TestGlobMatch/?oo_foo (0.00s)2237 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2238 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2239 --- PASS: TestGlobMatch/fo?_foo (0.00s)2240 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2241 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2242 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2243 --- PASS: TestGlobMatch/*/*_foo (0.00s)22442026/10/07 07:43:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40595/oidc22452026/10/07 07:43:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42345/oidc2246--- PASS: TestValidateToken_BoundSubjectMismatch (0.02s)2247--- PASS: TestValidateToken_ValidToken (0.02s)22482026/10/07 07:43:14 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12322492026/10/07 07:43:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38535/oidc2250--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.03s)22512026/10/07 07:43:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42281/oidc2252--- PASS: TestValidateToken_WrongAudience (0.04s)2253--- PASS: TestPins_TopLevelShorthand (0.04s)22542026/10/07 07:43:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43535/oidc22552026/10/07 07:43:14 http: TLS handshake error from 127.0.0.1:41512: remote error: tls: bad certificate2256--- PASS: TestNewValidator_KubernetesRequiresCA (0.04s)22572026/10/07 07:43:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45919/oidc2258--- PASS: TestValidateToken_BoundClaimsMismatch (0.05s)22592026/10/07 07:43:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32893/oidc2260--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.05s)2261--- PASS: TestValidateToken_Expired (0.05s)22622026/10/07 07:43:14 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:350392263--- PASS: TestValidateToken_KubernetesServiceAccount (0.11s)22642026/10/07 07:43:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42021/oidc2265--- PASS: TestScopes_Rules (0.14s)22662026/10/07 07:43:14 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:35049/oidc22672026/10/07 07:43:14 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:42103/oidc2268--- PASS: TestValidateToken_MultipleProviders (0.14s)22692026/10/07 07:43:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33411/oidc22702026/10/07 07:43:14 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:45221/oidc2271--- PASS: TestPins_ReservedForMatchingRule (0.21s)2272--- PASS: TestValidateToken_NoMatchingProvider (0.21s)2273PASS2274Running hook tests...2275=== RUN TestSendPathsEmpty2276=== PAUSE TestSendPathsEmpty2277=== RUN TestQueueEnqueueAndFetch2278=== PAUSE TestQueueEnqueueAndFetch2279=== RUN TestQueueDeduplication2280=== PAUSE TestQueueDeduplication2281=== RUN TestQueueRemove2282=== PAUSE TestQueueRemove2283=== RUN TestQueueFetchBatchLimit2284=== PAUSE TestQueueFetchBatchLimit2285=== RUN TestQueueRetryMovesToBack2286=== PAUSE TestQueueRetryMovesToBack2287=== RUN TestQueueFetchRemoveLifecycle2288=== PAUSE TestQueueFetchRemoveLifecycle2289=== RUN TestQueueConcurrentWriters2290=== PAUSE TestQueueConcurrentWriters2291=== RUN TestQueueRemoveLargeClosure2292=== PAUSE TestQueueRemoveLargeClosure2293=== RUN TestServerClientIntegration2294--- PASS: TestServerClientIntegration (0.00s)2295=== RUN TestServerQueueError22962026/10/07 07:43:14 ERROR Failed to queue paths error="permission denied" count=12297--- PASS: TestServerQueueError (0.00s)2298=== RUN TestGetListenerSocketActivation2299 server_test.go:219: === RUN TestGetListenerSocketActivation2300 --- PASS: TestGetListenerSocketActivation (0.00s)2301 PASS2302 2303--- PASS: TestGetListenerSocketActivation (0.01s)2304=== RUN TestDrainIsolatesPoisonPath2305=== PAUSE TestDrainIsolatesPoisonPath2306=== RUN TestRunNotBlockedByPoisonHead2307=== PAUSE TestRunNotBlockedByPoisonHead2308=== RUN TestDrainGivesUpWhenServerDown2309=== PAUSE TestDrainGivesUpWhenServerDown2310=== RUN TestFailedPathPrunedByLaterClosure2311=== PAUSE TestFailedPathPrunedByLaterClosure2312=== RUN TestWorkerUploadsAndRemoves2313=== PAUSE TestWorkerUploadsAndRemoves2314=== RUN TestWorkerSkipsGCdPaths2315=== PAUSE TestWorkerSkipsGCdPaths2316=== RUN TestWorkerPrunesClosureDeps2317=== PAUSE TestWorkerPrunesClosureDeps2318=== RUN TestDrainTimeout2319=== PAUSE TestDrainTimeout2320=== CONT TestSendPathsEmpty2321=== CONT TestDrainTimeout2322--- PASS: TestSendPathsEmpty (0.00s)2323=== CONT TestDrainIsolatesPoisonPath2324=== CONT TestQueueFetchBatchLimit2325=== CONT TestQueueRemove2326=== CONT TestQueueDeduplication2327=== CONT TestQueueEnqueueAndFetch2328=== CONT TestQueueRetryMovesToBack2329=== CONT TestQueueConcurrentWriters2330=== CONT TestQueueFetchRemoveLifecycle2331=== CONT TestQueueRemoveLargeClosure2332=== CONT TestWorkerUploadsAndRemoves2333=== CONT TestDrainGivesUpWhenServerDown2334=== CONT TestWorkerSkipsGCdPaths2335=== CONT TestFailedPathPrunedByLaterClosure2336=== CONT TestWorkerPrunesClosureDeps2337=== CONT TestRunNotBlockedByPoisonHead23382026/10/07 07:43:14 INFO Upload queue status pending=223392026/10/07 07:43:14 INFO Uploading batch count=123402026/10/07 07:43:14 INFO Uploading batch count=123412026/10/07 07:43:14 INFO Uploading batch count=423422026/10/07 07:43:14 ERROR Upload failed error="upload failed" count=423432026/10/07 07:43:14 ERROR Upload failed error="upload failed" count=123442026/10/07 07:43:14 INFO Upload queue status pending=223452026/10/07 07:43:14 INFO Uploading batch count=223462026/10/07 07:43:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath690863549/002/bbb2347--- PASS: TestQueueEnqueueAndFetch (0.02s)23482026/10/07 07:43:14 INFO Uploading batch count=223492026/10/07 07:43:14 ERROR Upload failed error="upload failed" count=223502026/10/07 07:43:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown135541933/002/a23512026/10/07 07:43:14 INFO Upload queue status pending=323522026/10/07 07:43:14 INFO Uploading batch count=22353--- PASS: TestQueueRemove (0.02s)23542026/10/07 07:43:14 INFO Upload queue status pending=223552026/10/07 07:43:14 INFO Uploading batch count=12356--- PASS: TestQueueRetryMovesToBack (0.02s)23572026/10/07 07:43:14 INFO Uploading batch count=12358--- PASS: TestQueueFetchBatchLimit (0.02s)23592026/10/07 07:43:14 ERROR Upload failed error="upload failed" count=123602026/10/07 07:43:14 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths655722231/002/nonexistent23612026/10/07 07:43:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown135541933/002/b23622026/10/07 07:43:14 INFO Uploading batch count=123632026/10/07 07:43:14 INFO Uploading batch count=12364--- PASS: TestQueueDeduplication (0.02s)2365--- PASS: TestQueueFetchRemoveLifecycle (0.02s)23662026/10/07 07:43:14 INFO Uploading batch count=123672026/10/07 07:43:14 ERROR Upload failed error="upload failed" count=123682026/10/07 07:43:14 INFO Uploading batch count=223692026/10/07 07:43:14 ERROR Upload failed error="upload failed" count=223702026/10/07 07:43:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown135541933/002/c23712026/10/07 07:43:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown135541933/002/d23722026/10/07 07:43:14 INFO Uploading batch count=123732026/10/07 07:43:14 ERROR Upload failed error="upload failed" count=12374--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)23752026/10/07 07:43:14 INFO Uploading batch count=223762026/10/07 07:43:14 ERROR Upload failed error="upload failed" count=223772026/10/07 07:43:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown135541933/002/e23782026/10/07 07:43:14 INFO Uploading batch count=123792026/10/07 07:43:14 ERROR Upload failed error="upload failed" count=123802026/10/07 07:43:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown135541933/002/f23812026/10/07 07:43:14 ERROR Drain finished with paths left in queue remaining=123822026/10/07 07:43:14 ERROR Drain finished with paths left in queue remaining=102383--- PASS: TestDrainIsolatesPoisonPath (0.03s)2384--- PASS: TestDrainGivesUpWhenServerDown (0.03s)2385--- PASS: TestWorkerPrunesClosureDeps (0.04s)2386--- PASS: TestWorkerSkipsGCdPaths (0.04s)2387--- PASS: TestWorkerUploadsAndRemoves (0.04s)2388--- PASS: TestQueueRemoveLargeClosure (0.06s)23892026/10/07 07:43:14 ERROR Upload failed error="context deadline exceeded" count=223902026/10/07 07:43:14 ERROR Drain finished with paths left in queue remaining=42391--- PASS: TestDrainTimeout (0.22s)2392--- PASS: TestQueueConcurrentWriters (0.37s)23932026/10/07 07:43:15 INFO Uploading batch count=123942026/10/07 07:43:15 INFO Uploading batch count=123952026/10/07 07:43:15 INFO Uploading batch count=123962026/10/07 07:43:15 ERROR Upload failed error="upload failed" count=123972026/10/07 07:43:15 INFO Uploading batch count=123982026/10/07 07:43:15 ERROR Upload failed error="upload failed" count=123992026/10/07 07:43:15 INFO Uploading batch count=124002026/10/07 07:43:15 ERROR Upload failed error="upload failed" count=124012026/10/07 07:43:15 INFO Uploading batch count=124022026/10/07 07:43:15 ERROR Upload failed error="upload failed" count=124032026/10/07 07:43:15 ERROR Drain finished with paths left in queue remaining=12404--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2405PASS2406Running signing tests...2407=== RUN TestExternalSigner2408=== PAUSE TestExternalSigner2409=== RUN TestExternalSignerWrongPublicKey2410=== PAUSE TestExternalSignerWrongPublicKey2411=== RUN TestExternalSignerErrors2412=== PAUSE TestExternalSignerErrors2413=== RUN TestExternalSignerRestartsAfterCrash2414=== PAUSE TestExternalSignerRestartsAfterCrash2415=== RUN TestExternalSignerProgramErrorKeepsProcess2416=== PAUSE TestExternalSignerProgramErrorKeepsProcess2417=== RUN TestExternalSignerClose2418=== PAUSE TestExternalSignerClose2419=== RUN TestExternalSignerRejectsInvalidPublicKey2420=== PAUSE TestExternalSignerRejectsInvalidPublicKey2421=== RUN TestExternalSignerCancellation2422=== PAUSE TestExternalSignerCancellation2423=== RUN TestGenerateFingerprint2424=== PAUSE TestGenerateFingerprint2425=== RUN TestParseSigningKey2426=== PAUSE TestParseSigningKey2427=== RUN TestSign2428=== PAUSE TestSign2429=== RUN TestSignBatch2430=== PAUSE TestSignBatch2431=== RUN TestNilKeyPublicKey2432=== PAUSE TestNilKeyPublicKey2433=== RUN TestSignErrors2434=== PAUSE TestSignErrors2435=== CONT TestExternalSigner2436=== CONT TestExternalSignerCancellation2437=== CONT TestSignBatch2438=== CONT TestParseSigningKey2439=== RUN TestParseSigningKey/valid_32-byte_key2440=== CONT TestGenerateFingerprint2441=== CONT TestSign2442=== RUN TestGenerateFingerprint/basic_with_references2443=== CONT TestExternalSignerProgramErrorKeepsProcess2444=== PAUSE TestGenerateFingerprint/basic_with_references2445=== CONT TestExternalSignerRejectsInvalidPublicKey2446=== RUN TestGenerateFingerprint/no_references2447=== PAUSE TestGenerateFingerprint/no_references2448=== RUN TestExternalSignerRejectsInvalidPublicKey/#002449=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2450=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2451=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2452=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2453=== RUN TestGenerateFingerprint/invalid_nar_hash_length2454=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2455=== RUN TestGenerateFingerprint/invalid_store_path_prefix2456=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2457=== CONT TestNilKeyPublicKey2458=== PAUSE TestParseSigningKey/valid_32-byte_key2459=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2460=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2461=== CONT TestExternalSignerErrors2462--- PASS: TestNilKeyPublicKey (0.00s)2463--- PASS: TestSign (0.00s)2464=== CONT TestExternalSignerRestartsAfterCrash2465=== CONT TestExternalSignerWrongPublicKey2466=== CONT TestSignErrors2467=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002468=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2469=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2470--- PASS: TestSignBatch (0.00s)2471=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2472=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2473=== RUN TestGenerateFingerprint/invalid_reference_prefix2474=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2475=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2476=== RUN TestSignErrors/nil_key2477=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2478=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2479=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2480=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2481=== CONT TestExternalSignerRejectsInvalidPublicKey/#002482=== RUN TestExternalSignerErrors/exit_on_request2483=== PAUSE TestExternalSignerErrors/exit_on_request2484=== RUN TestExternalSignerErrors/invalid_JSON2485=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2486=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2487=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2488=== RUN TestParseSigningKey/no_colon2489=== PAUSE TestParseSigningKey/no_colon2490=== PAUSE TestSignErrors/nil_key2491=== CONT TestGenerateFingerprint/invalid_reference_prefix2492=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2493=== CONT TestGenerateFingerprint/invalid_store_path_prefix2494=== CONT TestGenerateFingerprint/invalid_nar_hash_length2495=== CONT TestGenerateFingerprint/no_references2496=== CONT TestGenerateFingerprint/basic_with_references2497--- PASS: TestGenerateFingerprint (0.00s)2498 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2499 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2500 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2501 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2502 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2503 --- PASS: TestGenerateFingerprint/no_references (0.00s)2504 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2505=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2506--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2507 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2508 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2509 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2510 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2511 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2512=== CONT TestExternalSignerClose2513=== PAUSE TestExternalSignerErrors/invalid_JSON2514=== RUN TestParseSigningKey/empty_name2515=== RUN TestExternalSignerErrors/wrong_signatures_shape2516=== RUN TestSignErrors/nil_narinfo2517=== PAUSE TestSignErrors/nil_narinfo2518=== PAUSE TestParseSigningKey/empty_name2519=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2520=== RUN TestSignErrors/invalid_narinfo2521=== RUN TestParseSigningKey/invalid_base642522=== PAUSE TestParseSigningKey/invalid_base642523=== RUN TestParseSigningKey/wrong_length2524=== PAUSE TestParseSigningKey/wrong_length2525=== RUN TestExternalSignerErrors/exit_at_startup2526=== PAUSE TestExternalSignerErrors/exit_at_startup2527=== RUN TestExternalSignerErrors/null2528=== PAUSE TestExternalSignerErrors/null2529=== CONT TestParseSigningKey/valid_32-byte_key2530=== CONT TestParseSigningKey/wrong_length2531=== CONT TestParseSigningKey/invalid_base642532=== CONT TestParseSigningKey/empty_name2533=== CONT TestParseSigningKey/no_colon2534=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2535--- PASS: TestParseSigningKey (0.00s)2536 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2537 --- PASS: TestParseSigningKey/wrong_length (0.00s)2538 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2539 --- PASS: TestParseSigningKey/empty_name (0.00s)2540 --- PASS: TestParseSigningKey/no_colon (0.00s)2541 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2542=== PAUSE TestSignErrors/invalid_narinfo2543=== RUN TestSignErrors/canceled2544=== PAUSE TestSignErrors/canceled2545=== RUN TestExternalSignerErrors/missing_signatures2546=== PAUSE TestExternalSignerErrors/missing_signatures2547=== RUN TestExternalSignerErrors/null_signatures2548=== PAUSE TestExternalSignerErrors/null_signatures2549=== RUN TestExternalSignerErrors/unrequested_key2550=== CONT TestSignErrors/nil_key2551=== CONT TestSignErrors/canceled2552=== CONT TestSignErrors/invalid_narinfo2553=== PAUSE TestExternalSignerErrors/unrequested_key2554=== RUN TestExternalSignerErrors/invalid_signature_base642555=== CONT TestSignErrors/nil_narinfo2556=== PAUSE TestExternalSignerErrors/invalid_signature_base642557--- PASS: TestSignErrors (0.00s)2558 --- PASS: TestSignErrors/nil_key (0.00s)2559 --- PASS: TestSignErrors/canceled (0.00s)2560 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2561 --- PASS: TestSignErrors/nil_narinfo (0.00s)2562=== RUN TestExternalSignerErrors/wrong_id2563=== PAUSE TestExternalSignerErrors/wrong_id2564=== RUN TestExternalSignerErrors/too_few_signatures2565=== PAUSE TestExternalSignerErrors/too_few_signatures2566=== RUN TestExternalSignerErrors/missing_signature_name2567=== PAUSE TestExternalSignerErrors/missing_signature_name2568=== RUN TestExternalSignerErrors/wrong_shape2569=== PAUSE TestExternalSignerErrors/wrong_shape2570=== RUN TestExternalSignerErrors/wrong_signature_name2571=== PAUSE TestExternalSignerErrors/wrong_signature_name2572=== RUN TestExternalSignerErrors/wrong_signature_length2573=== PAUSE TestExternalSignerErrors/wrong_signature_length2574=== RUN TestExternalSignerErrors/program_error2575=== PAUSE TestExternalSignerErrors/program_error2576=== CONT TestExternalSignerErrors/exit_on_request2577=== CONT TestExternalSignerErrors/wrong_signature_length2578=== CONT TestExternalSignerErrors/wrong_signature_name2579=== CONT TestExternalSignerErrors/unrequested_key2580=== CONT TestExternalSignerErrors/null2581=== CONT TestExternalSignerErrors/program_error2582=== CONT TestExternalSignerErrors/wrong_shape2583=== CONT TestExternalSignerErrors/null_signatures2584=== CONT TestExternalSignerErrors/too_few_signatures2585=== CONT TestExternalSignerErrors/invalid_signature_base642586=== CONT TestExternalSignerErrors/wrong_id2587=== CONT TestExternalSignerErrors/exit_at_startup2588=== CONT TestExternalSignerErrors/missing_signatures2589=== CONT TestExternalSignerErrors/wrong_signatures_shape2590=== CONT TestExternalSignerErrors/invalid_JSON2591=== CONT TestExternalSignerErrors/missing_signature_name2592--- PASS: TestExternalSignerWrongPublicKey (0.01s)2593--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.01s)2594--- PASS: TestExternalSignerClose (0.00s)2595--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2596--- PASS: TestExternalSigner (0.01s)2597--- PASS: TestExternalSignerErrors (0.00s)2598 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2599 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)2600 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2601 --- PASS: TestExternalSignerErrors/null (0.01s)2602 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2603 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2604 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2605 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2606 --- PASS: TestExternalSignerErrors/program_error (0.01s)2607 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2608 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)2609 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2610 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2611 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2612 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2613 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2614--- PASS: TestExternalSignerCancellation (0.02s)2615PASS2616Running OpenBao signer tests...2617=== RUN TestSign2618=== PAUSE TestSign2619=== RUN TestSignErrors2620=== PAUSE TestSignErrors2621=== RUN TestServe2622=== PAUSE TestServe2623=== RUN TestServeRejectsGarbage2624=== PAUSE TestServeRejectsGarbage2625=== CONT TestSign2626=== CONT TestSignErrors2627=== CONT TestServe2628=== RUN TestSignErrors/http_error2629=== PAUSE TestSignErrors/http_error2630=== RUN TestSignErrors/invalid_json2631=== PAUSE TestSignErrors/invalid_json2632=== RUN TestSignErrors/no_prefix2633=== PAUSE TestSignErrors/no_prefix2634=== CONT TestServeRejectsGarbage2635=== RUN TestSignErrors/invalid_base642636--- PASS: TestServeRejectsGarbage (0.00s)2637--- PASS: TestServe (0.00s)2638=== PAUSE TestSignErrors/invalid_base642639=== CONT TestSignErrors/http_error2640=== CONT TestSignErrors/no_prefix2641=== CONT TestSignErrors/invalid_json2642=== CONT TestSignErrors/invalid_base642643--- PASS: TestSign (0.00s)2644--- PASS: TestSignErrors (0.00s)2645 --- PASS: TestSignErrors/invalid_base64 (0.00s)2646 --- PASS: TestSignErrors/invalid_json (0.00s)2647 --- PASS: TestSignErrors/http_error (0.00s)2648 --- PASS: TestSignErrors/no_prefix (0.00s)2649PASS