niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #408
· raw
1tribuchet: building on mac022Running 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.04s)23=== RUN TestDumpPathCaseHackCollision24--- PASS: TestDumpPathCaseHackCollision (0.00s)25=== RUN TestSupersededNARStillUploadsListing26=== PAUSE TestSupersededNARStillUploadsListing27=== RUN TestDumpPathMatchesNix28=== PAUSE TestDumpPathMatchesNix29=== RUN TestDumpPathSingleFile30=== PAUSE TestDumpPathSingleFile31=== RUN TestDumpPathWriterError32=== PAUSE TestDumpPathWriterError33=== RUN TestEncodeNixBase3234=== PAUSE TestEncodeNixBase3235=== RUN TestEncodeNixBase32WithRealHash36=== PAUSE TestEncodeNixBase32WithRealHash37=== RUN TestConvertHashToNix3238=== PAUSE TestConvertHashToNix3239=== RUN TestGetStorePathHash40=== PAUSE TestGetStorePathHash41=== RUN TestPathInfoHashCompatibility42=== PAUSE TestPathInfoHashCompatibility43=== RUN TestParsePathInfoJSON44=== PAUSE TestParsePathInfoJSON45=== RUN TestParsePathInfoJSONMultiplePaths46=== PAUSE TestParsePathInfoJSONMultiplePaths47=== RUN TestPathInfoCACompatibility48=== PAUSE TestPathInfoCACompatibility49=== RUN TestRateLimiterFeedback50=== PAUSE TestRateLimiterFeedback51=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess52=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess53=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer54=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer55=== RUN TestResolveStorePath56=== PAUSE TestResolveStorePath57=== RUN TestDoWithRetry_BodyReplayedViaGetBody58=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody59=== RUN TestRetryTimeoutOutlastsMaxRetries60=== PAUSE TestRetryTimeoutOutlastsMaxRetries61=== RUN TestDoWithRetry_FinalResponseBodyReadable62=== PAUSE TestDoWithRetry_FinalResponseBodyReadable63=== RUN TestShellSplit64=== PAUSE TestShellSplit65=== RUN TestShellSplitErrors66=== PAUSE TestShellSplitErrors67=== RUN TestStreamPushReportsEveryPath68=== PAUSE TestStreamPushReportsEveryPath69=== RUN TestStreamPushBatchesUnderLoad70=== PAUSE TestStreamPushBatchesUnderLoad71=== RUN TestStreamPushIsolatesFailures72=== PAUSE TestStreamPushIsolatesFailures73=== RUN TestStreamPushGivesUpOnDeadServer74=== PAUSE TestStreamPushGivesUpOnDeadServer75=== RUN TestStreamPushRequestLine76=== PAUSE TestStreamPushRequestLine77=== RUN TestStreamPushReportsSignatures78=== PAUSE TestStreamPushReportsSignatures79=== RUN TestStreamPushReportsSkippedPaths80=== PAUSE TestStreamPushReportsSkippedPaths81=== RUN TestClientSignaturesByStorePath82=== PAUSE TestClientSignaturesByStorePath83=== RUN TestStreamPushStopsWhenCanceled84=== PAUSE TestStreamPushStopsWhenCanceled85=== RUN TestSetClientTLS86=== PAUSE TestSetClientTLS87=== RUN TestSetClientTLSDoesNotMutateDefaultTransport88=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport89=== RUN TestSetClientTLSErrors90=== PAUSE TestSetClientTLSErrors91=== RUN TestStaticToken92=== PAUSE TestStaticToken93=== RUN TestFileTokenReadsAndCaches94=== PAUSE TestFileTokenReadsAndCaches95=== RUN TestFileTokenMissing96=== PAUSE TestFileTokenMissing97=== RUN TestFileTokenEmpty98=== PAUSE TestFileTokenEmpty99=== RUN TestScriptTokenNoExpiryRerunsEveryCall100=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall101=== RUN TestScriptTokenCachesUntilRefresh102=== PAUSE TestScriptTokenCachesUntilRefresh103=== RUN TestScriptTokenEmptyToken104=== PAUSE TestScriptTokenEmptyToken105=== RUN TestScriptTokenBadJSON106=== PAUSE TestScriptTokenBadJSON107=== RUN TestScriptTokenScriptFails108=== PAUSE TestScriptTokenScriptFails109=== RUN TestScriptTokenEmptyCommand110=== PAUSE TestScriptTokenEmptyCommand111=== CONT TestDoServerRequestAttachesToken112=== CONT TestRetryTimeoutOutlastsMaxRetries113=== CONT TestParsePathInfoJSONMultiplePaths114=== CONT TestGetStorePathHash115=== CONT TestSetClientTLS116=== RUN TestGetStorePathHash/valid_store_path117=== PAUSE TestGetStorePathHash/valid_store_path118=== RUN TestGetStorePathHash/basename_without_hyphen_should_error119=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error120=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error121=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error122=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error123=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error124=== CONT TestConvertHashToNix32125=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths126=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths127=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths128=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths129=== CONT TestScriptTokenScriptFails130=== CONT TestEncodeNixBase32WithRealHash131=== CONT TestScriptTokenBadJSON132=== CONT TestScriptTokenEmptyToken133=== CONT TestScriptTokenCachesUntilRefresh134=== CONT TestScriptTokenNoExpiryRerunsEveryCall135=== CONT TestFileTokenEmpty136=== CONT TestFileTokenMissing137=== CONT TestFileTokenReadsAndCaches138=== CONT TestStaticToken139=== CONT TestSetClientTLSErrors140=== CONT TestDumpPathWriterError141=== CONT TestSetClientTLSDoesNotMutateDefaultTransport142=== CONT TestEncodeNixBase32143=== CONT TestDoWithRetry_BodyReplayedViaGetBody144=== CONT TestResolveStorePath145=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer146=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess147=== CONT TestRateLimiterFeedback148=== CONT TestPathInfoCACompatibility149=== CONT TestScriptTokenEmptyCommand150=== RUN TestConvertHashToNix32/SRI_format_to_Nix32151--- PASS: TestEncodeNixBase32WithRealHash (0.00s)152=== CONT TestPartSizeForNAR153=== RUN TestPartSizeForNAR/zero_stays_at_minimum154=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum155=== RUN TestPartSizeForNAR/small_stays_at_minimum156=== PAUSE TestPartSizeForNAR/small_stays_at_minimum157=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum158=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum159=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts160=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts161=== RUN TestPartSizeForNAR/1_TiB162=== PAUSE TestPartSizeForNAR/1_TiB163=== RUN TestPartSizeForNAR/5_TiB_S3_max_object164=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object165=== RUN TestPartSizeForNAR/capped_at_5_GiB166=== PAUSE TestPartSizeForNAR/capped_at_5_GiB167=== RUN TestRateLimiterFeedback/429_enables_limiter168=== PAUSE TestRateLimiterFeedback/429_enables_limiter169=== RUN TestRateLimiterFeedback/503_enables_limiter170=== PAUSE TestRateLimiterFeedback/503_enables_limiter171=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter172=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter173=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter174=== RUN TestEncodeNixBase32/test_string_hash175=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter1762026/10/10 19:42:13 WARN Rate limiter enabled after throttle name=server-test rate=5177=== CONT TestDumpPathMatchesNix178=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32179--- PASS: TestStaticToken (0.00s)180=== CONT TestDumpPathSingleFile181=== CONT TestSupersededNARStillUploadsListing182--- PASS: TestScriptTokenEmptyCommand (0.00s)183--- PASS: TestFileTokenEmpty (0.00s)1842026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:49232185=== PAUSE TestEncodeNixBase32/test_string_hash186=== CONT TestUploadMultipart_SupersededByPeer187--- PASS: TestScriptTokenScriptFails (0.01s)188=== CONT TestCaseHackSuffix189--- PASS: TestDoServerRequestAttachesToken (0.01s)190=== CONT TestUploadMultipart_PartsInParallel191=== RUN TestPathInfoCACompatibility/null_ca_field192=== PAUSE TestPathInfoCACompatibility/null_ca_field193=== RUN TestPathInfoCACompatibility/old_string_format_-_text194=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text195=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive196=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive197=== RUN TestPathInfoCACompatibility/new_structured_format_-_text198=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text199=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method200=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method201=== RUN TestSetClientTLS/rejects_connection_without_client_cert202=== CONT TestFilterOversizedClosures203--- PASS: TestFileTokenReadsAndCaches (0.00s)204=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert205=== RUN TestConvertHashToNix32/already_Nix32_format206=== PAUSE TestConvertHashToNix32/already_Nix32_format207=== RUN TestConvertHashToNix32/invalid_format208=== RUN TestFilterOversizedClosures/no_limit_keeps_everything209=== CONT TestPathInfoHashCompatibility210=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything211=== RUN TestEncodeNixBase32/empty_input212=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)213=== RUN TestUploadMultipart_SupersededByPeer/exists214=== PAUSE TestUploadMultipart_SupersededByPeer/exists215=== RUN TestUploadMultipart_SupersededByPeer/missing216=== PAUSE TestUploadMultipart_SupersededByPeer/missing217=== PAUSE TestConvertHashToNix32/invalid_format218=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica219=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)220=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon221=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon222=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI223=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI224=== RUN TestSetClientTLSErrors/missing_cert_file225=== PAUSE TestSetClientTLSErrors/missing_cert_file226=== PAUSE TestEncodeNixBase32/empty_input227--- PASS: TestFileTokenMissing (0.01s)228=== RUN TestSupersededNARStillUploadsListing/small_NAR229=== PAUSE TestSupersededNARStillUploadsListing/small_NAR230=== RUN TestSupersededNARStillUploadsListing/dump_cut_short231=== CONT TestRegisterUploadedObjectReusesConnections232=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short233=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails234=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails2352026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:49232236=== CONT TestStreamPushGivesUpOnDeadServer237=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA238=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA239=== RUN TestSetClientTLS/preserves_debug_logging_transport240=== PAUSE TestSetClientTLS/preserves_debug_logging_transport241=== CONT TestParsePathInfoJSON242=== RUN TestParsePathInfoJSON/Nix_format243=== PAUSE TestParsePathInfoJSON/Nix_format244=== RUN TestParsePathInfoJSON/Lix_format245=== PAUSE TestParsePathInfoJSON/Lix_format246=== RUN TestParsePathInfoJSON/empty_input247=== CONT TestStreamPushStopsWhenCanceled248--- PASS: TestStreamPushStopsWhenCanceled (0.00s)249=== PAUSE TestParsePathInfoJSON/empty_input250=== RUN TestParsePathInfoJSON/whitespace_only251=== CONT TestClientSignaturesByStorePath252=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512253=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512254=== PAUSE TestParsePathInfoJSON/whitespace_only255=== CONT TestStreamPushReportsSignatures256=== CONT TestStreamPushReportsSkippedPaths2572026/10/10 19:42:13 INFO Garbage collection started258=== RUN TestParsePathInfoJSON/invalid_JSON259=== RUN TestSetClientTLSErrors/missing_key_file260=== PAUSE TestParsePathInfoJSON/invalid_JSON261=== CONT TestStreamPushRequestLine262=== PAUSE TestSetClientTLSErrors/missing_key_file263=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped264=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun265--- PASS: TestClientSignaturesByStorePath (0.00s)266--- PASS: TestStreamPushReportsSkippedPaths (0.00s)267=== RUN TestSetClientTLSErrors/missing_ca_file268=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped269=== RUN TestFilterOversizedClosures/all_closures_skipped270=== PAUSE TestFilterOversizedClosures/all_closures_skipped271=== PAUSE TestSetClientTLSErrors/missing_ca_file272=== RUN TestSetClientTLSErrors/invalid_ca_file273=== PAUSE TestSetClientTLSErrors/invalid_ca_file274=== CONT TestStreamPushIsolatesFailures275=== CONT TestStreamPushReportsEveryPath2762026/10/10 19:42:13 ERROR Upload failed error=boom count=1277=== CONT TestStreamPushBatchesUnderLoad2782026/10/10 19:42:13 WARN Rate limiter enabled after throttle name=server-test rate=52792026/10/10 19:42:13 ERROR Upload failed error="bad path" count=3280--- PASS: TestStreamPushReportsEveryPath (0.00s)281--- PASS: TestStreamPushReportsSignatures (0.00s)2822026/10/10 19:42:13 ERROR Upload failed error=boom count=1283=== CONT TestShellSplitErrors284--- PASS: TestShellSplitErrors (0.00s)2852026/10/10 19:42:13 ERROR Upload failed error="connection refused" count=202862026/10/10 19:42:13 ERROR Server seems unavailable, giving up on batch untried=17287=== CONT TestDoWithRetry_FinalResponseBodyReadable2882026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:49237289=== CONT TestShellSplit290--- PASS: TestShellSplit (0.00s)291=== CONT TestGetStorePathHash/valid_store_path292--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)293--- PASS: TestStreamPushIsolatesFailures (0.00s)294=== CONT TestGetStorePathHash/basename_without_hyphen_should_error295=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error296=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths297=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error298=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths299--- PASS: TestGetStorePathHash (0.00s)300 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)301 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)302 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)303 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)304=== CONT TestPartSizeForNAR/zero_stays_at_minimum305=== CONT TestPartSizeForNAR/capped_at_5_GiB306=== CONT TestPartSizeForNAR/5_TiB_S3_max_object307=== CONT TestPartSizeForNAR/1_TiB308=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts309=== CONT TestPartSizeForNAR/small_stays_at_minimum310=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum311--- PASS: TestPartSizeForNAR (0.00s)312 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)313 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)314 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)315 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)316 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)317 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)318 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)319=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter320--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)321 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)322 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)323=== CONT TestRateLimiterFeedback/429_enables_limiter324=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter325--- PASS: TestScriptTokenBadJSON (0.01s)326=== CONT TestRateLimiterFeedback/503_enables_limiter327--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)328=== CONT TestPathInfoCACompatibility/null_ca_field329=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method330=== CONT TestPathInfoCACompatibility/new_structured_format_-_text331=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive332=== CONT TestPathInfoCACompatibility/old_string_format_-_text333--- PASS: TestPathInfoCACompatibility (0.00s)334 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)335 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)336 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)337 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)338 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)339=== CONT TestUploadMultipart_SupersededByPeer/exists340--- PASS: TestResolveStorePath (0.01s)341=== CONT TestConvertHashToNix32/SRI_format_to_Nix32342--- PASS: TestScriptTokenEmptyToken (0.01s)343=== CONT TestConvertHashToNix32/already_Nix32_format344=== CONT TestConvertHashToNix32/invalid_format345=== CONT TestEncodeNixBase32/test_string_hash346=== CONT TestSupersededNARStillUploadsListing/small_NAR347--- PASS: TestConvertHashToNix32 (0.01s)348 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)349 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)350 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)351=== CONT TestEncodeNixBase32/empty_input352--- PASS: TestEncodeNixBase32 (0.01s)353 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)354 --- PASS: TestEncodeNixBase32/empty_input (0.00s)355=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3562026/10/10 19:42:13 INFO Uploading abc-hello (1.0GB)3572026/10/10 19:42:13 INFO Uploading abc-hello (1.0GB)3582026/10/10 19:42:13 WARN Rate limiter enabled after throttle name=server-test rate=53592026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:492993602026/10/10 19:42:13 WARN Rate limiter backed off name=server-test rate=5361--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)362=== CONT TestSupersededNARStillUploadsListing/dump_cut_short363=== CONT TestUploadMultipart_SupersededByPeer/missing3642026/10/10 19:42:13 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=03652026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:492323662026/10/10 19:42:13 WARN Rate limiter enabled after throttle name=server-test rate=53672026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:492483682026/10/10 19:42:13 WARN Rate limiter backed off name=server-test rate=5369=== CONT TestSetClientTLS/rejects_connection_without_client_cert3702026/10/10 19:42:13 WARN Rate limiter backed off name=server-test rate=53712026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:49237372=== CONT TestSetClientTLS/preserves_debug_logging_transport3732026/10/10 19:42:13 WARN Rate limiter enabled after throttle name=server-test rate=53742026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:492793752026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:49232376--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)377=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA378=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)3792026/10/10 19:42:13 WARN Rate limiter backed off name=server-test rate=5380--- PASS: TestRateLimiterFeedback (0.00s)381 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)382 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)383 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)384 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)385=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon386=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI387=== CONT TestParsePathInfoJSON/Nix_format388=== CONT TestParsePathInfoJSON/whitespace_only389=== CONT TestParsePathInfoJSON/invalid_JSON390=== CONT TestParsePathInfoJSON/empty_input391=== CONT TestParsePathInfoJSON/Lix_format392--- PASS: TestParsePathInfoJSON (0.00s)393 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)394 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)395 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)396 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)397 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)398=== CONT TestFilterOversizedClosures/no_limit_keeps_everything399=== CONT TestSetClientTLSErrors/missing_cert_file400=== CONT TestFilterOversizedClosures/all_closures_skipped4012026/10/10 19:42:13 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=50402=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped4032026/10/10 19:42:13 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=2000404--- PASS: TestFilterOversizedClosures (0.00s)405 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)406 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)407 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)408=== CONT TestSetClientTLSErrors/missing_ca_file409=== CONT TestSetClientTLSErrors/missing_key_file410=== CONT TestSetClientTLSErrors/invalid_ca_file411=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512412--- PASS: TestPathInfoHashCompatibility (0.00s)413 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)414 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)415 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)416 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)417--- PASS: TestSetClientTLSErrors (0.01s)418 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)419 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)420 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)421 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)4222026/10/10 19:42:13 WARN Garbage collection finished on another replica. Its statistics are not available here423--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)424 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)425 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)426--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)4272026/10/10 19:42:13 INFO Garbage collection started4282026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:49232429--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)430--- PASS: TestStreamPushRequestLine (0.02s)4312026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:492324322026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:492324332026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:492324342026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:492324352026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:492324362026/10/10 19:42:13 http: TLS handshake error from 127.0.0.1:49337: remote error: tls: bad certificate4372026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:49232438--- PASS: TestSetClientTLS (0.01s)439 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)440 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)441 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)4422026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:492324432026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:49232444--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)445--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)4462026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:492324472026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:492324482026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:492324492026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:49232450--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)4512026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:492324522026/10/10 19:42:13 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:49232453--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.05s)454--- PASS: TestDumpPathSingleFile (0.06s)455--- PASS: TestCaseHackSuffix (0.06s)456--- PASS: TestDumpPathWriterError (0.06s)457--- PASS: TestDumpPathMatchesNix (0.10s)458--- PASS: TestStreamPushBatchesUnderLoad (0.10s)4592026/10/10 19:42:13 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:49236/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:49236/api/uploads/complete4602026/10/10 19:42:13 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4612026/10/10 19:42:13 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:49236/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:49236/api/uploads/complete4622026/10/10 19:42:13 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4632026/10/10 19:42:13 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:49236/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:49236/api/uploads/complete4642026/10/10 19:42:13 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"465--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.20s)4662026/10/10 19:42:13 INFO Uploading abc-hello (1.0GB)4672026/10/10 19:42:13 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:49331/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:49331/part/24682026/10/10 19:42:13 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"469--- PASS: TestUploadMultipart_PartsInParallel (0.62s)470--- PASS: TestSupersededNARStillUploadsListing (0.01s)471 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)472 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.01s)473 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.82s)474--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)475PASS476Running server tests...477The files belonging to this database system will be owned by user "_tribuchetbld7".478This user must also own the server process.479480The database cluster will be initialized with locale "C".481The default database encoding has accordingly been set to "SQL_ASCII".482The default text search configuration will be set to "english".483484Data page checksums are enabled.485486creating directory /private/var/tb/7/scratch/fa1433502527f7cf/build/postgres1236157822/data ... ok487creating subdirectories ... ok488selecting dynamic shared memory implementation ... posix489selecting default "max_connections" ... 100490selecting default "shared_buffers" ... 128MB491selecting default time zone ... UTC492creating configuration files ... ok493running bootstrap script ... ok494performing post-bootstrap initialization ... ok495syncing data to disk ... ok496497initdb: warning: enabling "trust" authentication for local connections498initdb: 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.499500Success. You can now start the database server using:501502 pg_ctl -D /private/var/tb/7/scratch/fa1433502527f7cf/build/postgres1236157822/data -l logfile start503504/private/var/tb/7/scratch/fa1433502527f7cf/build/postgres1236157822:5432 - no response5052026-10-10 19:42:15.111 UTC [19427] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5062026-10-10 19:42:15.111 UTC [19427] LOG: listening on Unix socket "/private/var/tb/7/scratch/fa1433502527f7cf/build/postgres1236157822/.s.PGSQL.5432"5072026-10-10 19:42:15.113 UTC [19434] LOG: database system was shut down at 2026-10-10 19:42:15 UTC5082026-10-10 19:42:15.114 UTC [19427] LOG: database system is ready to accept connections509/private/var/tb/7/scratch/fa1433502527f7cf/build/postgres1236157822:5432 - accepting connections510{"timestamp":"2026-10-10T19:42:15.329514Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"55829a82-5f6e-4570-83b7-b1f1ec8ba6fe","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(3)"}511=== RUN TestService_AuthMiddleware512=== PAUSE TestService_AuthMiddleware513=== RUN TestService_AuthMiddleware_MTLSProxyHeader514=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader515=== RUN TestService_AuthMiddleware_MTLSBoundSubjects516=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects517=== RUN TestService_ReadAuthMiddleware518=== PAUSE TestService_ReadAuthMiddleware519=== RUN TestService_AuthMiddleware_OIDC520=== PAUSE TestService_AuthMiddleware_OIDC521=== RUN TestService_RequireScope_OIDC522=== PAUSE TestService_RequireScope_OIDC523=== RUN TestService_ReadScope_PublicByDefault524=== PAUSE TestService_ReadScope_PublicByDefault525=== RUN TestCacheConfigHandler526=== PAUSE TestCacheConfigHandler527=== RUN TestCacheStatsHandler528=== PAUSE TestCacheStatsHandler529=== RUN TestClientCADerivations530=== PAUSE TestClientCADerivations531=== RUN TestClientErrorHandling532=== PAUSE TestClientErrorHandling533=== RUN TestClientIntegration534=== PAUSE TestClientIntegration535=== RUN TestClientMultipleUploads536=== PAUSE TestClientMultipleUploads537=== RUN TestClientWithDependencies538=== PAUSE TestClientWithDependencies539=== RUN TestClientSharedPathCommittedMidPush540=== PAUSE TestClientSharedPathCommittedMidPush541=== RUN TestPinProtectsFromGC542=== PAUSE TestPinProtectsFromGC543=== RUN TestClientPushesUseOnePush544=== PAUSE TestClientPushesUseOnePush545=== RUN TestClientFallsBackToClosures546=== PAUSE TestClientFallsBackToClosures547=== RUN TestDeleteClosuresRacingPins548=== PAUSE TestDeleteClosuresRacingPins549=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock550=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock551=== RUN TestResolveDBConnectionString552=== PAUSE TestResolveDBConnectionString553=== RUN TestConnectWaitsForAPeerMigration554=== PAUSE TestConnectWaitsForAPeerMigration555=== RUN TestLeadElectsOneAndHandsOver556=== PAUSE TestLeadElectsOneAndHandsOver557=== RUN TestLeadIncumbentWinsAfterRestart5582026/10/10 19:42:15 INFO lead: acquired remote=192.0.2.1:12345592026/10/10 19:42:16 INFO lead: released remote=192.0.2.1:12345602026/10/10 19:42:16 INFO lead: acquired remote=192.0.2.1:12345612026/10/10 19:42:17 INFO lead: released remote=192.0.2.1:1234562--- PASS: TestLeadIncumbentWinsAfterRestart (1.94s)563=== RUN TestLeadIncumbentAnnouncesAtOnce564=== PAUSE TestLeadIncumbentAnnouncesAtOnce565=== RUN TestLeadEndsOnShutdown566=== PAUSE TestLeadEndsOnShutdown567=== RUN TestLeadEndsWhenItsConnectionHangs5682026/10/10 19:42:17 INFO lead: acquired remote=192.0.2.1:12345692026-10-10 19:42:18.952 UTC [19481] FATAL: terminating connection due to administrator command5702026/10/10 19:42:19 INFO lead: acquired remote=192.0.2.1:12345712026/10/10 19:42:20 WARN lead: lock connection lost error="timeout: context deadline exceeded"5722026/10/10 19:42:20 INFO lead: released remote=192.0.2.1:12345732026/10/10 19:42:20 INFO lead: released remote=192.0.2.1:1234574--- PASS: TestLeadEndsWhenItsConnectionHangs (2.97s)575=== RUN TestGCAdvisoryLockBlocksConcurrentRun576=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun577=== RUN TestGCBugBareHashReferences578=== PAUSE TestGCBugBareHashReferences579=== RUN TestGCMetrics580=== PAUSE TestGCMetrics581=== RUN TestPushDedupSurvivesConcurrentGC582=== PAUSE TestPushDedupSurvivesConcurrentGC583=== RUN TestDeduplicatedObjectsRecordedAsPending584=== PAUSE TestDeduplicatedObjectsRecordedAsPending585=== RUN TestGCSweepSkipsPendingObjects586=== PAUSE TestGCSweepSkipsPendingObjects587=== RUN TestTombstonedObjectOfferedWithoutWaiting588=== PAUSE TestTombstonedObjectOfferedWithoutWaiting589=== RUN TestGCSweepDeliversEachKeyOnce590=== PAUSE TestGCSweepDeliversEachKeyOnce591=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection592=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection593=== RUN TestForceGCDuringPushOffersSweptObject594=== PAUSE TestForceGCDuringPushOffersSweptObject595=== RUN TestFailedS3DeleteKeepsTombstone596=== PAUSE TestFailedS3DeleteKeepsTombstone597=== RUN TestSweepSkipsRowsLockedByPush598=== PAUSE TestSweepSkipsRowsLockedByPush599=== RUN TestRegisterCompletedObjectNeedsPendingRow600=== PAUSE TestRegisterCompletedObjectNeedsPendingRow601=== RUN TestGetExistingObjectsLocksRows602=== PAUSE TestGetExistingObjectsLocksRows603=== RUN TestSweepRechecksPendingAfterLocking604=== PAUSE TestSweepRechecksPendingAfterLocking605=== RUN TestPushWaitsForSweepHoldingRow606=== PAUSE TestPushWaitsForSweepHoldingRow607=== RUN TestCommitRacingPendingCleanupKeepsObjects608=== PAUSE TestCommitRacingPendingCleanupKeepsObjects609=== RUN TestGCEndsOnShutdown610=== PAUSE TestGCEndsOnShutdown611=== RUN TestGCTaskStore_StartNew612=== PAUSE TestGCTaskStore_StartNew613=== RUN TestGCTaskStore_DeduplicateSameParams614=== PAUSE TestGCTaskStore_DeduplicateSameParams615=== RUN TestGCTaskStore_ConflictDifferentParams616=== PAUSE TestGCTaskStore_ConflictDifferentParams617=== RUN TestGCTaskStore_GetEmpty618=== PAUSE TestGCTaskStore_GetEmpty619=== RUN TestGCTaskStore_GetReturnsLatest620=== PAUSE TestGCTaskStore_GetReturnsLatest621=== RUN TestGCTaskStore_CompletedAllowsNewTask622=== PAUSE TestGCTaskStore_CompletedAllowsNewTask623=== RUN TestGCTaskStore_PhaseUpdates624=== PAUSE TestGCTaskStore_PhaseUpdates625=== RUN TestGCTaskStore_Fail626=== PAUSE TestGCTaskStore_Fail627=== RUN TestGracefulShutdownDrainsInflight628=== PAUSE TestGracefulShutdownDrainsInflight629=== RUN TestService_healthCheckHandler630=== PAUSE TestService_healthCheckHandler631=== RUN TestService_readinessHandler632=== PAUSE TestService_readinessHandler633=== RUN TestGenerateLandingPage634=== PAUSE TestGenerateLandingPage635=== RUN TestCacheConfigHandlerMaxNarSize636=== PAUSE TestCacheConfigHandlerMaxNarSize637=== RUN TestCreatePendingClosureRejectsOversizedNAR638=== PAUSE TestCreatePendingClosureRejectsOversizedNAR639=== RUN TestNARDeduplicationMetadataUploadBug640=== PAUSE TestNARDeduplicationMetadataUploadBug641=== RUN TestMetricsInventory642=== PAUSE TestMetricsInventory643=== RUN TestMetricsCommit644=== PAUSE TestMetricsCommit645=== RUN TestService_NativeMTLS646=== PAUSE TestService_NativeMTLS647=== RUN TestServerTLSConfig648=== PAUSE TestServerTLSConfig649=== RUN TestMultipartCleanup650=== PAUSE TestMultipartCleanup651=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded652=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded653=== RUN TestPendingCleanupUsesOneCutoff654=== PAUSE TestPendingCleanupUsesOneCutoff655=== RUN TestObjectStatsTrigger656=== PAUSE TestObjectStatsTrigger657=== RUN TestObjectStatsLargeCommit658=== PAUSE TestObjectStatsLargeCommit659=== RUN TestOrphanedObjectsGC660=== PAUSE TestOrphanedObjectsGC661=== RUN TestOrphanedObjectsGCStressTest662=== PAUSE TestOrphanedObjectsGCStressTest663=== RUN TestCreatePin_ReservedPins664=== PAUSE TestCreatePin_ReservedPins665=== RUN TestPresentReportsOnlyClosureRoots666=== PAUSE TestPresentReportsOnlyClosureRoots667=== RUN TestPresentRefreshesOnlyStaleClosures668=== PAUSE TestPresentRefreshesOnlyStaleClosures669=== RUN TestPresentNotReportedWhileGCDeletesClosure670=== PAUSE TestPresentNotReportedWhileGCDeletesClosure671=== RUN TestParseSingleRange672=== PAUSE TestParseSingleRange673=== RUN TestProxyHeadersOnlyTrustedOnSocket6742026/10/10 19:42:20 INFO Starting HTTP server address=127.0.0.1:493616752026/10/10 19:42:20 INFO Starting HTTP server address=proxy.sock6762026/10/10 19:42:20 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6772026/10/10 19:42:20 INFO Shutdown signal received, draining in-flight requests timeout=10s678--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)679=== RUN TestIsValidCachePath680=== PAUSE TestIsValidCachePath681=== RUN TestReadProxyNarinfo682=== PAUSE TestReadProxyNarinfo683=== RUN TestReadProxyNarinfoAlreadyDecompressed684=== PAUSE TestReadProxyNarinfoAlreadyDecompressed685=== RUN TestReadProxyContentNegotiation686=== PAUSE TestReadProxyContentNegotiation687=== RUN TestReadProxyNarStreaming688=== PAUSE TestReadProxyNarStreaming689=== RUN TestReadProxy404690=== PAUSE TestReadProxy404691=== RUN TestReadProxyInvalidPath692=== PAUSE TestReadProxyInvalidPath693=== RUN TestReadProxyHead694=== PAUSE TestReadProxyHead695=== RUN TestReadProxyOutlastsServerWriteTimeout696=== PAUSE TestReadProxyOutlastsServerWriteTimeout697=== RUN TestReadProxyConditionalGet698=== PAUSE TestReadProxyConditionalGet699=== RUN TestReadProxyRootRedirectsToIndexHTML700=== PAUSE TestReadProxyRootRedirectsToIndexHTML701=== RUN TestReadProxyDisabled702=== PAUSE TestReadProxyDisabled703=== RUN TestReadRedirectNar704=== PAUSE TestReadRedirectNar705=== RUN TestReadRedirectKeepsNarinfoProxied706=== PAUSE TestReadRedirectKeepsNarinfoProxied707=== RUN TestReadProxyRangeRequest708=== PAUSE TestReadProxyRangeRequest709=== RUN TestReadRedirectUsesPublicS3URL710=== PAUSE TestReadRedirectUsesPublicS3URL711=== RUN TestPush_OverlappingRootsStoreOneRowPerKey712=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey713=== RUN TestPush_CompleteCommitsEveryRoot714=== PAUSE TestPush_CompleteCommitsEveryRoot715=== RUN TestPush_RepeatedRootCommitsOnce716=== PAUSE TestPush_RepeatedRootCommitsOnce717=== RUN TestPush_CompleteWaitsForCleanupOfThePush718=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush719=== RUN TestPush_RootsAreLockedInByteOrder720=== PAUSE TestPush_RootsAreLockedInByteOrder721=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit722=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit723=== RUN TestPush_RejectsBadRequests724=== PAUSE TestPush_RejectsBadRequests725=== RUN TestPush_SignsNarinfosOfItsPendingObjects726=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects727=== RUN TestRedundantMultipartUpload728=== PAUSE TestRedundantMultipartUpload729=== RUN TestCompleteMultipartUpload_ErrorButObjectExists730=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists731=== RUN TestCompletedNarNotReofferedAcrossClosures732=== PAUSE TestCompletedNarNotReofferedAcrossClosures733=== RUN TestPresignedUploadRegisteredBeforeCommit734=== PAUSE TestPresignedUploadRegisteredBeforeCommit735=== RUN TestService_Rustfstest736=== PAUSE TestService_Rustfstest737=== RUN TestParseSize738=== PAUSE TestParseSize739=== RUN TestSkippedUploadsHandler740=== PAUSE TestSkippedUploadsHandler741=== RUN TestSystemdListenerNotActivated742--- PASS: TestSystemdListenerNotActivated (0.00s)743=== RUN TestWatchdogBeatsWhenHealthy744--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)745=== RUN TestWatchdogSkipsWhenUnhealthy7462026/10/10 19:42:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/10/10 19:42:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7482026/10/10 19:42:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7492026/10/10 19:42:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7502026/10/10 19:42:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7512026/10/10 19:42:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7522026/10/10 19:42:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7532026/10/10 19:42:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7542026/10/10 19:42:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7552026/10/10 19:42:20 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"756--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)757=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle758=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle759=== RUN TestProxyWriteTimeout760=== PAUSE TestProxyWriteTimeout761=== RUN TestPendingClosureWriteTimeout762=== PAUSE TestPendingClosureWriteTimeout763=== RUN TestIsValidUploadKey764=== PAUSE TestIsValidUploadKey765=== RUN TestUploadHandlersRejectInvalidKeys766=== PAUSE TestUploadHandlersRejectInvalidKeys767=== RUN TestUploadHandlersRejectOversizedBody768=== PAUSE TestUploadHandlersRejectOversizedBody769=== RUN TestService_cleanupPendingClosuresHandler770=== PAUSE TestService_cleanupPendingClosuresHandler771=== RUN TestService_createPendingClosureHandler772=== PAUSE TestService_createPendingClosureHandler773=== RUN TestService_verifyS3Integrity774=== PAUSE TestService_verifyS3Integrity775=== RUN TestCompleteMultipartUnregistered776=== PAUSE TestCompleteMultipartUnregistered777=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT778=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT779=== CONT TestService_AuthMiddleware780=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT781=== CONT TestOrphanedObjectsGCStressTest782=== CONT TestForceGCDuringPushOffersSweptObject783=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows784=== CONT TestClientCADerivations785=== CONT TestDeleteClosuresRacingPins786=== CONT TestSweepSkipsRowsLockedByPush787=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows788=== CONT TestPresentReportsOnlyClosureRoots789=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check790=== CONT TestCreatePin_ReservedPins791=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check792=== CONT TestFailedS3DeleteKeepsTombstone793=== CONT TestPush_CompleteWaitsForCleanupOfThePush794=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection795=== CONT TestCompleteMultipartUnregistered796=== CONT TestService_verifyS3Integrity797=== CONT TestService_createPendingClosureHandler798=== CONT TestService_cleanupPendingClosuresHandler799=== CONT TestUploadHandlersRejectOversizedBody800=== CONT TestUploadHandlersRejectInvalidKeys801=== CONT TestIsValidUploadKey802=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info803=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info804=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal805=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal806=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key807=== CONT TestPendingClosureWriteTimeout808=== RUN TestIsValidUploadKey/narinfo809=== PAUSE TestIsValidUploadKey/narinfo810=== RUN TestIsValidUploadKey/nar_zst811=== CONT TestGCSweepDeliversEachKeyOnce812=== CONT TestProxyWriteTimeout813=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle814=== CONT TestPresentRefreshesOnlyStaleClosures815=== CONT TestTombstonedObjectOfferedWithoutWaiting816=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key817=== RUN TestPendingClosureWriteTimeout/empty818=== PAUSE TestIsValidUploadKey/nar_zst819=== RUN TestIsValidUploadKey/nar_xz820=== PAUSE TestIsValidUploadKey/nar_xz821=== RUN TestIsValidUploadKey/nar_plain822=== PAUSE TestIsValidUploadKey/nar_plain823=== RUN TestIsValidUploadKey/listing824=== RUN TestProxyWriteTimeout/narinfo825=== PAUSE TestPendingClosureWriteTimeout/empty826=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key827=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key828=== PAUSE TestIsValidUploadKey/listing829=== RUN TestIsValidUploadKey/build_log830=== PAUSE TestIsValidUploadKey/build_log831=== RUN TestIsValidUploadKey/build_log_home-manager_file832=== PAUSE TestIsValidUploadKey/build_log_home-manager_file833=== RUN TestIsValidUploadKey/build_log_plus_in_name834=== PAUSE TestIsValidUploadKey/build_log_plus_in_name835=== RUN TestIsValidUploadKey/build_log_question_mark836=== PAUSE TestIsValidUploadKey/build_log_question_mark837=== RUN TestIsValidUploadKey/build_log_equals838=== PAUSE TestIsValidUploadKey/build_log_equals839=== RUN TestIsValidUploadKey/realisation840=== PAUSE TestIsValidUploadKey/realisation841=== RUN TestIsValidUploadKey/realisation_plus_in_output842=== PAUSE TestIsValidUploadKey/realisation_plus_in_output843=== RUN TestIsValidUploadKey/nix-cache-info844=== PAUSE TestIsValidUploadKey/nix-cache-info845=== RUN TestIsValidUploadKey/index.html846=== PAUSE TestIsValidUploadKey/index.html847=== RUN TestIsValidUploadKey/narinfo_key,_nar_type848=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type849=== RUN TestIsValidUploadKey/nar_key,_narinfo_type850=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type851=== RUN TestIsValidUploadKey/listing_key,_narinfo_type852=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type853=== RUN TestIsValidUploadKey/traversal854=== PAUSE TestIsValidUploadKey/traversal855=== RUN TestIsValidUploadKey/traversal_nar856=== PAUSE TestIsValidUploadKey/traversal_nar857=== RUN TestIsValidUploadKey/absolute858=== PAUSE TestIsValidUploadKey/absolute859=== RUN TestIsValidUploadKey/empty_key860=== PAUSE TestIsValidUploadKey/empty_key861=== RUN TestIsValidUploadKey/unknown_type862=== PAUSE TestIsValidUploadKey/unknown_type863=== PAUSE TestProxyWriteTimeout/narinfo864=== RUN TestProxyWriteTimeout/1_GiB_nar865=== PAUSE TestProxyWriteTimeout/1_GiB_nar866=== RUN TestProxyWriteTimeout/10_GiB_nar867=== PAUSE TestProxyWriteTimeout/10_GiB_nar868=== RUN TestProxyWriteTimeout/unknown_size869=== PAUSE TestProxyWriteTimeout/unknown_size870=== CONT TestSkippedUploadsHandler871=== CONT TestGCSweepSkipsPendingObjects8722026/10/10 19:42:20 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000873=== RUN TestPendingClosureWriteTimeout/400_objects874=== PAUSE TestPendingClosureWriteTimeout/400_objects875=== RUN TestPendingClosureWriteTimeout/670k_objects876=== PAUSE TestPendingClosureWriteTimeout/670k_objects877=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline878=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline879=== CONT TestParseSize880--- PASS: TestParseSize (0.00s)881=== CONT TestService_Rustfstest882=== CONT TestDeduplicatedObjectsRecordedAsPending883--- PASS: TestSkippedUploadsHandler (0.01s)884=== CONT TestPresignedUploadRegisteredBeforeCommit885=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure886=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure887=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart888=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart889=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts890=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts891=== CONT TestCompletedNarNotReofferedAcrossClosures8922026/10/10 19:42:20 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49364/oidc8932026/10/10 19:42:21 INFO Aborted multipart uploads count=0 kept=08942026/10/10 19:42:21 WARN Force mode enabled - objects will be deleted immediately without grace period8952026/10/10 19:42:22 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=08962026/10/10 19:42:22 INFO Vacuumed table table=pending_closures8972026/10/10 19:42:22 INFO Vacuumed table table=pending_objects8982026/10/10 19:42:22 INFO Vacuumed table table=multipart_uploads8992026/10/10 19:42:22 INFO Vacuumed table table=closures9002026/10/10 19:42:22 INFO Vacuumed table table=objects901--- PASS: TestGCSweepDeliversEachKeyOnce (1.40s)902=== CONT TestCompleteMultipartUpload_ErrorButObjectExists9032026/10/10 19:42:22 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"904--- PASS: TestService_AuthMiddleware (1.52s)905=== CONT TestPushDedupSurvivesConcurrentGC906--- PASS: TestPresentReportsOnlyClosureRoots (1.88s)907=== CONT TestRedundantMultipartUpload9082026/10/10 19:42:22 INFO Aborted multipart uploads count=0 kept=09092026/10/10 19:42:22 WARN Force mode enabled - objects will be deleted immediately without grace period9102026/10/10 19:42:22 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=09112026/10/10 19:42:22 INFO Vacuumed table table=pending_closures9122026/10/10 19:42:22 INFO Vacuumed table table=pending_objects9132026/10/10 19:42:22 INFO Vacuumed table table=multipart_uploads9142026/10/10 19:42:22 INFO Vacuumed table table=closures9152026/10/10 19:42:22 INFO Vacuumed table table=objects9162026/10/10 19:42:22 INFO Aborted multipart uploads count=0 kept=09172026/10/10 19:42:23 WARN Force mode enabled - objects will be deleted immediately without grace period9182026/10/10 19:42:23 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=09192026/10/10 19:42:23 INFO Vacuumed table table=pending_closures9202026/10/10 19:42:23 INFO Vacuumed table table=pending_objects9212026/10/10 19:42:23 INFO Vacuumed table table=multipart_uploads9222026/10/10 19:42:23 INFO Vacuumed table table=closures9232026/10/10 19:42:23 INFO Vacuumed table table=objects924--- PASS: TestSweepSkipsRowsLockedByPush (2.33s)925=== CONT TestGCMetrics9262026/10/10 19:42:23 INFO Received uploads request method=POST path=/api/pending_closures927--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.64s)928=== CONT TestPush_SignsNarinfosOfItsPendingObjects9292026/10/10 19:42:23 INFO Received uploads request method=POST path=/api/pending_closures930--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (3.01s)931=== CONT TestGCBugBareHashReferences9322026/10/10 19:42:23 INFO Received uploads request method=POST path=/api/pending_closures9332026/10/10 19:42:23 INFO Aborted multipart uploads count=0 kept=09342026/10/10 19:42:23 WARN Force mode enabled - objects will be deleted immediately without grace period9352026/10/10 19:42:23 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."9362026/10/10 19:42:23 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."937--- PASS: TestFailedS3DeleteKeepsTombstone (3.22s)938=== CONT TestPush_RejectsBadRequests9392026/10/10 19:42:24 INFO Received push request method=POST path=/api/pushes9402026/10/10 19:42:24 INFO Received uploads request method=POST path=/api/pending_closures9412026/10/10 19:42:24 INFO Received uploads request method=POST path=/api/pending_closures9422026/10/10 19:42:24 INFO Received uploads request method=POST path=/api/pending_closures9432026-10-10 19:42:24.430 UTC [19591] ERROR: Push does not exist: id=19442026-10-10 19:42:24.430 UTC [19591] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE9452026-10-10 19:42:24.430 UTC [19591] STATEMENT: SELECT commit_push($1)946--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (3.67s)947=== CONT TestGCAdvisoryLockBlocksConcurrentRun9482026/10/10 19:42:24 INFO Received uploads request method=POST path=/api/pending_closures949--- PASS: TestDeleteClosuresRacingPins (4.39s)950=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9512026/10/10 19:42:25 INFO Received uploads request method=POST path=/api/pending_closures952=== NAME TestClientCADerivations953 client_ca_test.go:136: Built CA derivation: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientCADerivations1648845688/001/store/pcax6dpdncdynsgzpifg3j1w7755mdvg-ca-test9542026/10/10 19:42:25 INFO Received uploads request method=POST path=/api/pending_closures9552026/10/10 19:42:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete956 client_ca_test.go:139: Found 1 dependencies (including self)9572026/10/10 19:42:25 INFO Aborted multipart uploads count=0 kept=09582026/10/10 19:42:25 WARN Force mode enabled - objects will be deleted immediately without grace period9592026/10/10 19:42:25 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=09602026/10/10 19:42:25 INFO Vacuumed table table=pending_closures9612026/10/10 19:42:25 INFO Vacuumed table table=pending_objects9622026/10/10 19:42:25 INFO Vacuumed table table=multipart_uploads9632026/10/10 19:42:25 INFO Vacuumed table table=closures9642026/10/10 19:42:25 INFO Vacuumed table table=objects9652026/10/10 19:42:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete966--- PASS: TestGCSweepSkipsPendingObjects (5.01s)967=== CONT TestLeadEndsOnShutdown9682026/10/10 19:42:25 INFO Received push request method=POST path=/api/pushes9692026/10/10 19:42:25 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YTk2NTg0NDQtYjY3MS00NjZmLWJhOTYtMzBlMmQxN2YyNjY3LjEyMTE5NzFiLWFjZGItNDdhMi1iYzg1LTJjMTJhZGNkMjVhNngxNzkxNjYxMzQ0MzM5NDQ5MDAw parts=109702026/10/10 19:42:25 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9712026/10/10 19:42:25 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9722026/10/10 19:42:25 INFO Uploading pcax6dpdncdynsgzpifg3j1w7755mdvg-ca-test (144B)9732026/10/10 19:42:25 INFO Completed upload id=1 objects=2 duration=9.866125ms9742026/10/10 19:42:25 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009752026/10/10 19:42:25 INFO Received uploads request method=POST path=/api/pending_closures9762026/10/10 19:42:25 INFO Starting cleanup of old closures method=DELETE path=/api/closures9772026/10/10 19:42:25 INFO Aborted multipart uploads count=0 kept=09782026/10/10 19:42:25 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"9792026/10/10 19:42:25 WARN Failed to register uploaded object key=pcax6dpdncdynsgzpifg3j1w7755mdvg.ls error="server returned 404: 404 page not found\n"9802026/10/10 19:42:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9812026/10/10 19:42:25 WARN Failed to register uploaded object key=log/4mlcacgsbig627dnp43lwhvh6pgnghsb-ca-test.drv error="server returned 404: 404 page not found\n"9822026/10/10 19:42:25 INFO Signed narinfos id=1 count=19832026/10/10 19:42:25 INFO Uploading 1 narinfos9842026/10/10 19:42:25 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=09852026/10/10 19:42:25 INFO Received complete push request method=POST path=/api/pushes/1/complete986--- PASS: TestPresentRefreshesOnlyStaleClosures (5.20s)9872026/10/10 19:42:25 WARN Failed to register uploaded object key=pcax6dpdncdynsgzpifg3j1w7755mdvg.narinfo error="server returned 404: 404 page not found\n"988=== CONT TestPush_RootsAreLockedInByteOrder9892026/10/10 19:42:25 INFO Vacuumed table table=pending_closures9902026/10/10 19:42:26 INFO Completed push id=1 objects=4 duration=31.732458ms9912026/10/10 19:42:26 INFO Upload complete. (308ms)9922026/10/10 19:42:26 INFO Vacuumed table table=pending_objects993=== NAME TestClientCADerivations994 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientCADerivations1648845688/001/store/pcax6dpdncdynsgzpifg3j1w7755mdvg-ca-test995 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst996 Compression: zstd997 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n998 NarSize: 144999 References: 1000 Deriver: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientCADerivations1648845688/001/store/4mlcacgsbig627dnp43lwhvh6pgnghsb-ca-test.drv1001 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1002 client_ca_test.go:185: Checking for realisation files in S3...1003 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1004 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache10052026/10/10 19:42:26 INFO Vacuumed table table=multipart_uploads10062026/10/10 19:42:26 INFO Vacuumed table table=closures1007 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket16?endpoint=http://localhost:49346®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientCADerivations1648845688/001/store'1008 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 110092026/10/10 19:42:26 INFO Vacuumed table table=objects10102026/10/10 19:42:26 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001011--- PASS: TestService_createPendingClosureHandler (5.41s)1012=== CONT TestLeadIncumbentAnnouncesAtOnce10132026/10/10 19:42:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10142026/10/10 19:42:26 INFO Received cleanup request method=DELETE path=/api/pending_closures1015--- PASS: TestClientCADerivations (5.50s)1016=== CONT TestConnectWaitsForAPeerMigration10172026/10/10 19:42:26 INFO Aborted multipart uploads count=0 kept=010182026/10/10 19:42:26 INFO Received uploads request method=POST path=/api/pending_closures10192026/10/10 19:42:26 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YTk2NTg0NDQtYjY3MS00NjZmLWJhOTYtMzBlMmQxN2YyNjY3Ljc1NjcxN2Y0LWY3MjUtNDAzMC04MGM4LTZlYzJhZWYxMmI2NHgxNzkxNjYxMzQ0NjY4ODIyMDAw parts=1010202026/10/10 19:42:26 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10212026/10/10 19:42:26 INFO Completed upload id=1 objects=2 duration=12.293459ms10222026/10/10 19:42:26 INFO Received uploads request method=POST path=/api/pending_closures10232026/10/10 19:42:26 INFO Received uploads request method=POST path=/api/pending_closures10242026/10/10 19:42:26 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10252026/10/10 19:42:26 WARN Found objects in DB but missing from S3, will re-upload count=11026--- PASS: TestService_verifyS3Integrity (5.56s)1027=== CONT TestResolveDBConnectionString1028=== RUN TestResolveDBConnectionString/flag_wins1029=== PAUSE TestResolveDBConnectionString/flag_wins1030=== RUN TestResolveDBConnectionString/file_when_flag_empty1031=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1032=== RUN TestResolveDBConnectionString/missing_file_is_an_error1033=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1034=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1035=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1036=== RUN TestResolveDBConnectionString/nothing_configured1037=== PAUSE TestResolveDBConnectionString/nothing_configured1038=== CONT TestLeadElectsOneAndHandsOver10392026/10/10 19:42:26 INFO Received cleanup request method=DELETE path=/api/pending_closures10402026/10/10 19:42:26 INFO Aborted multipart uploads count=1 kept=010412026/10/10 19:42:26 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10422026-10-10 19:42:26.387 UTC [19562] ERROR: Closure does not exist: id=110432026-10-10 19:42:26.387 UTC [19562] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10442026-10-10 19:42:26.387 UTC [19562] STATEMENT: -- name: CommitPendingClosure :one1045 SELECT commit_pending_closure($1::bigint)::bigint1046 1047--- PASS: TestService_cleanupPendingClosuresHandler (5.62s)1048=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock10492026/10/10 19:42:26 INFO Received uploads request method=POST path=/api/pending_closures10502026/10/10 19:42:26 INFO Received uploads request method=POST path=/api/pending_closures10512026/10/10 19:42:26 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10522026/10/10 19:42:26 INFO Received uploads request method=POST path=/api/pending_closures1053--- PASS: TestPresignedUploadRegisteredBeforeCommit (6.10s)1054=== CONT TestReadProxyOutlastsServerWriteTimeout1055--- PASS: TestService_Rustfstest (6.40s)1056=== CONT TestPush_RepeatedRootCommitsOnce10572026/10/10 19:42:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10582026/10/10 19:42:27 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1059--- PASS: TestCompleteMultipartUnregistered (6.88s)1060=== CONT TestPush_CompleteCommitsEveryRoot10612026/10/10 19:42:28 INFO Received uploads request method=POST path=/api/pending_closures1062--- PASS: TestDeduplicatedObjectsRecordedAsPending (7.31s)1063=== CONT TestPush_OverlappingRootsStoreOneRowPerKey10642026/10/10 19:42:28 INFO Received uploads request method=POST path=/api/pending_closures1065--- PASS: TestTombstonedObjectOfferedWithoutWaiting (7.76s)1066=== CONT TestReadRedirectUsesPublicS3URL10672026/10/10 19:42:28 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10682026/10/10 19:42:28 WARN Refused reserved pin name=worker-x86_64-linux10692026/10/10 19:42:28 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10702026/10/10 19:42:28 INFO Received create pin request method=POST path=/api/pins/my-app10712026/10/10 19:42:28 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10722026/10/10 19:42:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1073--- PASS: TestCreatePin_ReservedPins (8.06s)1074=== CONT TestReadProxyRangeRequest10752026/10/10 19:42:28 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YTk2NTg0NDQtYjY3MS00NjZmLWJhOTYtMzBlMmQxN2YyNjY3LmEzNGMzODE1LWYwMTYtNDE5Yi1iYWE0LTY1ZDM1ZjlmYWZlOXgxNzkxNjYxMzQ2NTk2MDAxMDAw parts=1210762026/10/10 19:42:28 INFO Received uploads request method=POST path=/api/pending_closures1077--- PASS: TestCompletedNarNotReofferedAcrossClosures (8.10s)1078=== CONT TestReadRedirectKeepsNarinfoProxied10792026/10/10 19:42:29 INFO Received uploads request method=POST path=/api/pending_closures10802026/10/10 19:42:29 INFO Received uploads request method=POST path=/api/pending_closures10812026/10/10 19:42:29 INFO Received uploads request method=POST path=/api/pending_closures1082=== NAME TestOrphanedObjectsGCStressTest1083 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains10842026/10/10 19:42:29 INFO Aborted multipart uploads count=0 kept=01085 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion10862026/10/10 19:42:29 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=010872026/10/10 19:42:29 INFO Received uploads request method=POST path=/api/pending_closures10882026/10/10 19:42:29 INFO Vacuumed table table=pending_closures10892026/10/10 19:42:29 WARN Rate limiter enabled after throttle name=s3-test rate=510902026/10/10 19:42:29 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1091=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1092 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101093 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001094--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (9.05s)1095=== CONT TestReadRedirectNar10962026/10/10 19:42:29 INFO Vacuumed table table=pending_objects10972026/10/10 19:42:29 INFO Vacuumed table table=multipart_uploads10982026/10/10 19:42:29 INFO Vacuumed table table=closures10992026/10/10 19:42:29 INFO Vacuumed table table=objects11002026/10/10 19:42:29 INFO Aborted multipart uploads count=0 kept=011012026/10/10 19:42:29 WARN Force mode enabled - objects will be deleted immediately without grace period11022026/10/10 19:42:29 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=011032026/10/10 19:42:29 INFO Vacuumed table table=pending_closures11042026/10/10 19:42:30 INFO Vacuumed table table=pending_objects11052026/10/10 19:42:30 INFO Vacuumed table table=multipart_uploads11062026/10/10 19:42:30 INFO Vacuumed table table=closures11072026/10/10 19:42:30 INFO Vacuumed table table=objects1108--- PASS: TestPushDedupSurvivesConcurrentGC (7.77s)1109=== CONT TestReadProxyDisabled11102026/10/10 19:42:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11112026/10/10 19:42:30 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTk2NTg0NDQtYjY3MS00NjZmLWJhOTYtMzBlMmQxN2YyNjY3Ljc0OGFiOWVkLTE1YjUtNDY4Mi05YmMzLTFjYzczOWRlZjEwN3gxNzkxNjYxMzQ5ODY3MjYzMDAw11122026/10/10 19:42:30 INFO Aborted multipart uploads count=0 kept=011132026/10/10 19:42:30 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTk2NTg0NDQtYjY3MS00NjZmLWJhOTYtMzBlMmQxN2YyNjY3Ljc0OGFiOWVkLTE1YjUtNDY4Mi05YmMzLTFjYzczOWRlZjEwN3gxNzkxNjYxMzQ5ODY3MjYzMDAw parts=11114--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (8.03s)1115=== CONT TestReadProxyRootRedirectsToIndexHTML11162026/10/10 19:42:30 WARN Force mode enabled - objects will be deleted immediately without grace period11172026/10/10 19:42:30 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=011182026/10/10 19:42:30 INFO Vacuumed table table=pending_closures11192026/10/10 19:42:30 INFO Vacuumed table table=pending_objects11202026/10/10 19:42:30 INFO Vacuumed table table=multipart_uploads11212026/10/10 19:42:30 INFO Vacuumed table table=closures11222026/10/10 19:42:30 INFO Vacuumed table table=objects1123--- PASS: TestGCMetrics (7.18s)1124=== CONT TestReadProxyConditionalGet11252026/10/10 19:42:30 INFO Received push request method=POST path=/api/pushes11262026/10/10 19:42:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11272026/10/10 19:42:30 INFO Signed narinfos id=1 count=111282026/10/10 19:42:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11292026/10/10 19:42:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11302026/10/10 19:42:30 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"11312026/10/10 19:42:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11322026/10/10 19:42:30 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"11332026/10/10 19:42:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11342026/10/10 19:42:30 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=111352026/10/10 19:42:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11362026/10/10 19:42:30 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1137--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (7.24s)1138=== CONT TestService_RequireScope_OIDC11392026/10/10 19:42:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49417/oidc1140--- PASS: TestGCBugBareHashReferences (7.38s)1141=== CONT TestClientSharedPathCommittedMidPush11422026/10/10 19:42:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1143=== RUN TestPush_RejectsBadRequests/no_objects1144=== PAUSE TestPush_RejectsBadRequests/no_objects1145=== RUN TestPush_RejectsBadRequests/bad_root1146=== PAUSE TestPush_RejectsBadRequests/bad_root1147=== RUN TestPush_RejectsBadRequests/root_not_in_objects1148=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1149=== RUN TestPush_RejectsBadRequests/no_roots1150=== PAUSE TestPush_RejectsBadRequests/no_roots1151=== CONT TestClientFallsBackToClosures11522026/10/10 19:42:31 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YTk2NTg0NDQtYjY3MS00NjZmLWJhOTYtMzBlMmQxN2YyNjY3Ljg2OTNmZDNlLTZjNzAtNDQzMS1iYTIzLTg2ZGEyYzA3ZWJmZHgxNzkxNjYxMzQ5MTY5NjcxMDAw parts=1211532026/10/10 19:42:31 INFO Received uploads request method=POST path=/api/pending_closures11542026/10/10 19:42:31 INFO Received uploads request method=POST path=/api/pending_closures11552026/10/10 19:42:31 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld7 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1156--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (7.16s)1157=== CONT TestClientPushesUseOnePush11582026/10/10 19:42:31 INFO Received push request method=POST path=/api/pushes11592026/10/10 19:42:32 INFO Received complete push request method=POST path=/api/pushes/1/complete11602026/10/10 19:42:32 INFO Completed push id=1 objects=4 duration=56.547125ms11612026/10/10 19:42:32 INFO Received push request method=POST path=/api/pushes11622026/10/10 19:42:32 INFO Aborted multipart uploads count=0 kept=011632026/10/10 19:42:32 WARN Force mode enabled - objects will be deleted immediately without grace period11642026/10/10 19:42:32 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=011652026/10/10 19:42:32 INFO lead: acquired remote=192.0.2.1:123411662026/10/10 19:42:32 INFO Vacuumed table table=pending_closures11672026/10/10 19:42:32 INFO Vacuumed table table=pending_objects11682026/10/10 19:42:32 INFO Vacuumed table table=multipart_uploads11692026/10/10 19:42:32 INFO Vacuumed table table=closures11702026/10/10 19:42:32 INFO Vacuumed table table=objects11712026/10/10 19:42:32 INFO Received complete push request method=POST path=/api/pushes/2/complete11722026/10/10 19:42:32 INFO Completed push id=2 objects=4 duration=6.318ms1173--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (7.35s)1174=== CONT TestPinProtectsFromGC11752026/10/10 19:42:32 INFO Received push request method=POST path=/api/pushes11762026-10-10 19:42:32.808 UTC [19689] ERROR: could not obtain lock on row in relation "closures"11772026-10-10 19:42:32.808 UTC [19689] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11782026-10-10 19:42:32.821 UTC [19689] ERROR: could not obtain lock on row in relation "closures"11792026-10-10 19:42:32.821 UTC [19689] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11802026-10-10 19:42:32.822 UTC [19689] ERROR: could not obtain lock on row in relation "closures"11812026-10-10 19:42:32.822 UTC [19689] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11822026-10-10 19:42:32.822 UTC [19689] ERROR: could not obtain lock on row in relation "closures"11832026-10-10 19:42:32.822 UTC [19689] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11842026-10-10 19:42:32.822 UTC [19689] ERROR: could not obtain lock on row in relation "closures"11852026-10-10 19:42:32.822 UTC [19689] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1186--- PASS: TestPush_RootsAreLockedInByteOrder (6.86s)1187=== CONT TestReadProxyContentNegotiation11882026/10/10 19:42:32 INFO lead: acquired remote=192.0.2.1:123411892026/10/10 19:42:32 INFO lead: released remote=192.0.2.1:12341190--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.81s)1191=== CONT TestReadProxyHead11922026/10/10 19:42:33 INFO lead: acquired remote=192.0.2.1:123411932026/10/10 19:42:33 INFO lead: released remote=192.0.2.1:12341194--- PASS: TestLeadEndsOnShutdown (7.50s)1195=== CONT TestReadProxyInvalidPath11962026/10/10 19:42:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11972026/10/10 19:42:33 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YTk2NTg0NDQtYjY3MS00NjZmLWJhOTYtMzBlMmQxN2YyNjY3LmZlMzkwN2FkLTU4NmEtNDUzZC05YzNhLTllZjI0YWQyOGYyNXgxNzkxNjYxMzUxMzg0NzEzMDAw error="Get \"http://127.0.0.1:1/bucket30/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11982026/10/10 19:42:33 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YTk2NTg0NDQtYjY3MS00NjZmLWJhOTYtMzBlMmQxN2YyNjY3LjIwZTA1YjYzLWMzMDMtNGM2YS05MDI4LWRkYTRmYmE4YTllNXgxNzkxNjYxMzUxMzMwMjA2MDAw parts=1211992026/10/10 19:42:33 INFO Received cleanup request method=DELETE path=/api/pending_closures12002026/10/10 19:42:33 INFO Aborted multipart uploads count=1 kept=01201--- PASS: TestRedundantMultipartUpload (10.88s)1202=== CONT TestReadProxy4041203=== NAME TestOrphanedObjectsGCStressTest1204 orphaned_objects_gc_test.go:503: Stress test completed successfully:1205 orphaned_objects_gc_test.go:504: - Active objects preserved: 201206 orphaned_objects_gc_test.go:505: - Objects deleted: 2101207 orphaned_objects_gc_test.go:506: - Total GC'd: 2101208--- PASS: TestOrphanedObjectsGCStressTest (13.30s)1209=== CONT TestReadProxyNarStreaming12102026/10/10 19:42:34 INFO Received push request method=POST path=/api/pushes1211--- PASS: TestConnectWaitsForAPeerMigration (8.21s)1212=== CONT TestClientMultipleUploads12132026/10/10 19:42:34 INFO lead: released remote=192.0.2.1:123412142026/10/10 19:42:34 INFO lead: acquired remote=192.0.2.1:123412152026/10/10 19:42:34 INFO Received complete push request method=POST path=/api/pushes/1/complete12162026/10/10 19:42:34 INFO Completed push id=1 objects=4 duration=26.227833ms1217--- PASS: TestPush_RepeatedRootCommitsOnce (7.34s)1218=== CONT TestClientWithDependencies12192026/10/10 19:42:34 INFO Received push request method=POST path=/api/pushes12202026/10/10 19:42:34 INFO Received complete push request method=POST path=/api/pushes/1/complete12212026/10/10 19:42:34 INFO Completed push id=1 objects=6 duration=61.31325ms1222--- PASS: TestPush_CompleteCommitsEveryRoot (7.23s)1223=== CONT TestCacheConfigHandler1224=== RUN TestCacheConfigHandler/full_config,_no_issuer1225=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1226=== RUN TestCacheConfigHandler/no_cache_url_configured1227=== PAUSE TestCacheConfigHandler/no_cache_url_configured1228=== RUN TestCacheConfigHandler/no_signing_keys1229=== PAUSE TestCacheConfigHandler/no_signing_keys1230=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1231=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1232=== CONT TestIsValidCachePath1233=== RUN TestIsValidCachePath/narinfo1234=== PAUSE TestIsValidCachePath/narinfo1235=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1236=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1237=== RUN TestIsValidCachePath/nar_zst1238=== PAUSE TestIsValidCachePath/nar_zst1239=== RUN TestIsValidCachePath/nar_xz1240=== PAUSE TestIsValidCachePath/nar_xz1241=== RUN TestIsValidCachePath/nar_bz21242=== PAUSE TestIsValidCachePath/nar_bz21243=== RUN TestIsValidCachePath/nar_uncompressed1244=== PAUSE TestIsValidCachePath/nar_uncompressed1245=== RUN TestIsValidCachePath/ls1246=== PAUSE TestIsValidCachePath/ls1247=== RUN TestIsValidCachePath/log1248=== PAUSE TestIsValidCachePath/log1249=== RUN TestIsValidCachePath/realisation1250=== PAUSE TestIsValidCachePath/realisation1251=== RUN TestIsValidCachePath/nix-cache-info1252=== PAUSE TestIsValidCachePath/nix-cache-info1253=== RUN TestIsValidCachePath/index.html1254=== PAUSE TestIsValidCachePath/index.html1255=== RUN TestIsValidCachePath/traversal_parent1256=== PAUSE TestIsValidCachePath/traversal_parent1257=== RUN TestIsValidCachePath/traversal_in_middle1258=== PAUSE TestIsValidCachePath/traversal_in_middle1259=== RUN TestIsValidCachePath/invalid_char_e1260=== PAUSE TestIsValidCachePath/invalid_char_e1261=== RUN TestIsValidCachePath/invalid_char_u1262=== PAUSE TestIsValidCachePath/invalid_char_u1263=== RUN TestIsValidCachePath/random_path1264=== PAUSE TestIsValidCachePath/random_path1265=== RUN TestIsValidCachePath/empty1266=== PAUSE TestIsValidCachePath/empty1267=== RUN TestIsValidCachePath/leading_slash1268=== PAUSE TestIsValidCachePath/leading_slash1269=== RUN TestIsValidCachePath/wrong_extension1270=== PAUSE TestIsValidCachePath/wrong_extension1271=== RUN TestIsValidCachePath/short_hash1272=== PAUSE TestIsValidCachePath/short_hash1273=== CONT TestCacheStatsHandler1274--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (8.51s)1275=== CONT TestReadProxyNarinfoAlreadyDecompressed12762026/10/10 19:42:34 INFO Received push request method=POST path=/api/pushes1277--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.95s)1278=== CONT TestService_ReadScope_PublicByDefault1279--- PASS: TestReadRedirectUsesPublicS3URL (6.71s)1280=== CONT TestReadProxyNarinfo1281--- PASS: TestReadProxyRangeRequest (6.65s)1282=== CONT TestService_healthCheckHandler12832026/10/10 19:42:35 INFO lead: released remote=192.0.2.1:12341284--- PASS: TestLeadElectsOneAndHandsOver (9.30s)1285=== CONT TestService_NativeMTLS1286--- PASS: TestReadRedirectKeepsNarinfoProxied (6.73s)1287=== CONT TestMetricsCommit1288--- PASS: TestReadRedirectNar (6.11s)1289=== CONT TestOrphanedObjectsGC1290--- PASS: TestReadProxyDisabled (6.09s)1291=== CONT TestObjectStatsLargeCommit1292--- PASS: TestReadProxyConditionalGet (6.13s)1293=== CONT TestObjectStatsTrigger1294--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.42s)1295=== CONT TestPendingCleanupUsesOneCutoff1296=== RUN TestService_RequireScope_OIDC/builder_may_write1297=== PAUSE TestService_RequireScope_OIDC/builder_may_write1298=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1299=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1300=== RUN TestService_RequireScope_OIDC/ops_may_admin1301=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1302=== RUN TestService_RequireScope_OIDC/ops_may_not_write1303=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1304=== RUN TestService_RequireScope_OIDC/reader_may_not_write1305=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1306=== RUN TestService_RequireScope_OIDC/static_token_may_admin1307=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1308=== RUN TestService_RequireScope_OIDC/static_token_may_write1309=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1310=== RUN TestService_RequireScope_OIDC/reader_may_read1311=== PAUSE TestService_RequireScope_OIDC/reader_may_read1312=== RUN TestService_RequireScope_OIDC/writer_implies_read1313=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1314=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1315=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1316=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1317=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1318=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1319=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1320=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1321=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1322=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1323=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1324=== CONT TestMetricsInventory13252026/10/10 19:42:37 INFO Received uploads request method=POST path=/api/pending_closures13262026/10/10 19:42:37 INFO Received uploads request method=POST path=/api/pending_closures13272026/10/10 19:42:37 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13282026/10/10 19:42:37 INFO Uploading v7rl1cjqsb1mxhz1z8r1yzcjwq31mq5r-shared-dep (136B)13292026/10/10 19:42:37 INFO Uploading 3v4avj10gbjppmlsh9fgx0as4ixipiq6-a (256B)13302026/10/10 19:42:37 WARN Failed to register uploaded object key=v7rl1cjqsb1mxhz1z8r1yzcjwq31mq5r.ls error="server returned 404: 404 page not found\n"13312026/10/10 19:42:37 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13322026/10/10 19:42:37 WARN Failed to register uploaded object key=xa6mj0w5hrb56ifvcrf9ng0sh0rz9i8f.ls error="server returned 404: 404 page not found\n"13332026/10/10 19:42:37 WARN Failed to register uploaded object key=3v4avj10gbjppmlsh9fgx0as4ixipiq6.ls error="server returned 404: 404 page not found\n"13342026/10/10 19:42:37 WARN Failed to register uploaded object key=nar/1yg7ggxb88gypbngbdd4qhkv42w3mqbh0i9d5hvq9afpy5rh0g5v.nar.zst error="server returned 404: 404 page not found\n"13352026/10/10 19:42:37 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13362026/10/10 19:42:37 INFO Signed narinfos id=1 count=213372026/10/10 19:42:37 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13382026/10/10 19:42:37 INFO Signed narinfos id=2 count=213392026/10/10 19:42:37 INFO Uploading 4 narinfos13402026/10/10 19:42:37 WARN Failed to register uploaded object key=xa6mj0w5hrb56ifvcrf9ng0sh0rz9i8f.narinfo error="server returned 404: 404 page not found\n"13412026/10/10 19:42:37 WARN Failed to register uploaded object key=v7rl1cjqsb1mxhz1z8r1yzcjwq31mq5r.narinfo error="server returned 404: 404 page not found\n"13422026/10/10 19:42:37 WARN Failed to register uploaded object key=3v4avj10gbjppmlsh9fgx0as4ixipiq6.narinfo error="server returned 404: 404 page not found\n"13432026/10/10 19:42:37 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13442026/10/10 19:42:37 WARN Failed to register uploaded object key=v7rl1cjqsb1mxhz1z8r1yzcjwq31mq5r.narinfo error="server returned 404: 404 page not found\n"13452026/10/10 19:42:37 INFO Received push request method=POST path=/api/pushes13462026/10/10 19:42:37 INFO Completed upload id=2 objects=6 duration=25.41325ms13472026/10/10 19:42:37 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13482026/10/10 19:42:37 INFO Completed upload id=1 objects=6 duration=577.25µs13492026/10/10 19:42:37 INFO Upload complete. (201ms)1350=== NAME TestClientFallsBackToClosures1351 client_pushes_test.go:112: Retrieved narinfo from S3:1352 StorePath: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientFallsBackToClosures1094146007/001/store/v7rl1cjqsb1mxhz1z8r1yzcjwq31mq5r-shared-dep1353 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1354 Compression: zstd1355 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821356 NarSize: 1361357 References: 1358 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n13592026/10/10 19:42:37 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)1360 client_pushes_test.go:112: Retrieved narinfo from S3:13612026/10/10 19:42:37 INFO Uploading j40gvlxzdrwqbg2nsl78i2jvaypqf1jc-shared-dep (136B)1362 StorePath: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientFallsBackToClosures1094146007/001/store/3v4avj10gbjppmlsh9fgx0as4ixipiq6-a1363 URL: nar/1yg7ggxb88gypbngbdd4qhkv42w3mqbh0i9d5hvq9afpy5rh0g5v.nar.zst1364 Compression: zstd1365 NarHash: sha256:1yg7ggxb88gypbngbdd4qhkv42w3mqbh0i9d5hvq9afpy5rh0g5v1366 NarSize: 2561367 References: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientFallsBackToClosures1094146007/001/store/v7rl1cjqsb1mxhz1z8r1yzcjwq31mq5r-shared-dep1368 CA: text:sha256:1idq5z6r5iqlsjh8l56087zmhaw8w3va8yza04sq54bvqnpmzavg13692026/10/10 19:42:37 INFO Uploading hlgb79266fg6gik8rqd2jsyhfjxdq91x-top (264B)1370 client_pushes_test.go:112: Retrieved narinfo from S3:1371 StorePath: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientFallsBackToClosures1094146007/001/store/xa6mj0w5hrb56ifvcrf9ng0sh0rz9i8f-b1372 URL: nar/1yg7ggxb88gypbngbdd4qhkv42w3mqbh0i9d5hvq9afpy5rh0g5v.nar.zst1373 Compression: zstd1374 NarHash: sha256:1yg7ggxb88gypbngbdd4qhkv42w3mqbh0i9d5hvq9afpy5rh0g5v1375 NarSize: 2561376 References: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientFallsBackToClosures1094146007/001/store/v7rl1cjqsb1mxhz1z8r1yzcjwq31mq5r-shared-dep1377 CA: text:sha256:1idq5z6r5iqlsjh8l56087zmhaw8w3va8yza04sq54bvqnpmzavg13782026/10/10 19:42:37 WARN Failed to register uploaded object key=nar/1frblp4nmxb2c70p0rgxy31xqq7vvslnjvv7jji4dip857fmjm64.nar.zst error="server returned 404: 404 page not found\n"13792026/10/10 19:42:37 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13802026/10/10 19:42:37 WARN Failed to register uploaded object key=hlgb79266fg6gik8rqd2jsyhfjxdq91x.ls error="server returned 404: 404 page not found\n"13812026/10/10 19:42:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13822026/10/10 19:42:37 WARN Failed to register uploaded object key=j40gvlxzdrwqbg2nsl78i2jvaypqf1jc.ls error="server returned 404: 404 page not found\n"13832026/10/10 19:42:37 INFO Signed narinfos id=1 count=213842026/10/10 19:42:37 INFO Uploading 2 narinfos13852026/10/10 19:42:37 WARN Failed to register uploaded object key=hlgb79266fg6gik8rqd2jsyhfjxdq91x.narinfo error="server returned 404: 404 page not found\n"13862026/10/10 19:42:37 INFO Received complete push request method=POST path=/api/pushes/1/complete13872026/10/10 19:42:37 WARN Failed to register uploaded object key=j40gvlxzdrwqbg2nsl78i2jvaypqf1jc.narinfo error="server returned 404: 404 page not found\n"1388--- PASS: TestClientFallsBackToClosures (6.56s)1389=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded13902026/10/10 19:42:37 INFO Completed push id=1 objects=6 duration=23.248542ms13912026/10/10 19:42:37 INFO Upload complete. (197ms)1392=== NAME TestClientSharedPathCommittedMidPush1393 client_integration_test.go:680: Retrieved narinfo from S3:1394 StorePath: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientSharedPathCommittedMidPush732995726/001/store/j40gvlxzdrwqbg2nsl78i2jvaypqf1jc-shared-dep1395 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1396 Compression: zstd1397 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821398 NarSize: 1361399 References: 1400 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1401 client_integration_test.go:680: Retrieved narinfo from S3:1402 StorePath: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientSharedPathCommittedMidPush732995726/001/store/hlgb79266fg6gik8rqd2jsyhfjxdq91x-top1403 URL: nar/1frblp4nmxb2c70p0rgxy31xqq7vvslnjvv7jji4dip857fmjm64.nar.zst1404 Compression: zstd1405 NarHash: sha256:1frblp4nmxb2c70p0rgxy31xqq7vvslnjvv7jji4dip857fmjm641406 NarSize: 2641407 References: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientSharedPathCommittedMidPush732995726/001/store/j40gvlxzdrwqbg2nsl78i2jvaypqf1jc-shared-dep1408 CA: text:sha256:0phx9ny0ldpkzwyf4h6hki6qijbffmzdrq7f0nr85ygg01fz29dm1409--- PASS: TestClientSharedPathCommittedMidPush (6.66s)1410=== CONT TestNARDeduplicationMetadataUploadBug14112026/10/10 19:42:38 INFO Received push request method=POST path=/api/pushes14122026/10/10 19:42:38 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14132026/10/10 19:42:38 INFO Uploading z2silag6sdcqb45dbnds0vhy0ksvzs98-a (256B)14142026/10/10 19:42:38 INFO Uploading d6x8zy41f0kzlfhv9z90z6h98yjfnxvz-shared-dep (136B)14152026/10/10 19:42:38 WARN Failed to register uploaded object key=d6x8zy41f0kzlfhv9z90z6h98yjfnxvz.ls error="server returned 404: 404 page not found\n"14162026/10/10 19:42:38 WARN Failed to register uploaded object key=47ni8xpxp1ri38l8k54dyyd9ihmkdjz7.ls error="server returned 404: 404 page not found\n"14172026/10/10 19:42:38 WARN Failed to register uploaded object key=z2silag6sdcqb45dbnds0vhy0ksvzs98.ls error="server returned 404: 404 page not found\n"14182026/10/10 19:42:38 WARN Failed to register uploaded object key=nar/1kj33y9jbn3919nlzfz352k6rk6i02xanmcl3ckspwgr0rby8y76.nar.zst error="server returned 404: 404 page not found\n"14192026/10/10 19:42:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14202026/10/10 19:42:38 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1421=== NAME TestPinProtectsFromGC1422 client_integration_test.go:731: Pinned store path: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestPinProtectsFromGC2558766644/001/store/dn812gicfyzwdmn41nr7jg5saka0mhah-pinned-file.txt1423 client_integration_test.go:732: Unpinned store path: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestPinProtectsFromGC2558766644/001/store/nprlq7lwl33rmmd6yvr097g7283gpifd-unpinned-file.txt14242026/10/10 19:42:38 INFO Signed narinfos id=1 count=314252026/10/10 19:42:38 INFO Uploading 3 narinfos1426--- PASS: TestReadProxyHead (5.06s)1427=== CONT TestMultipartCleanup14282026/10/10 19:42:38 WARN Failed to register uploaded object key=d6x8zy41f0kzlfhv9z90z6h98yjfnxvz.narinfo error="server returned 404: 404 page not found\n"14292026/10/10 19:42:38 WARN Failed to register uploaded object key=47ni8xpxp1ri38l8k54dyyd9ihmkdjz7.narinfo error="server returned 404: 404 page not found\n"14302026/10/10 19:42:38 INFO Received complete push request method=POST path=/api/pushes/1/complete14312026/10/10 19:42:38 WARN Failed to register uploaded object key=z2silag6sdcqb45dbnds0vhy0ksvzs98.narinfo error="server returned 404: 404 page not found\n"14322026/10/10 19:42:38 INFO Completed push id=1 objects=8 duration=20.571958ms14332026/10/10 19:42:38 INFO Upload complete. (170ms)1434=== NAME TestClientPushesUseOnePush1435 client_pushes_test.go:97: Retrieved narinfo from S3:1436 StorePath: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientPushesUseOnePush1281427186/001/store/d6x8zy41f0kzlfhv9z90z6h98yjfnxvz-shared-dep1437 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1438 Compression: zstd1439 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821440 NarSize: 1361441 References: 1442 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1443 client_pushes_test.go:97: Retrieved narinfo from S3:1444 StorePath: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientPushesUseOnePush1281427186/001/store/z2silag6sdcqb45dbnds0vhy0ksvzs98-a1445 URL: nar/1kj33y9jbn3919nlzfz352k6rk6i02xanmcl3ckspwgr0rby8y76.nar.zst1446 Compression: zstd1447 NarHash: sha256:1kj33y9jbn3919nlzfz352k6rk6i02xanmcl3ckspwgr0rby8y761448 NarSize: 2561449 References: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientPushesUseOnePush1281427186/001/store/d6x8zy41f0kzlfhv9z90z6h98yjfnxvz-shared-dep1450 CA: text:sha256:047j5128ziy83xn6pbqsxpg4s1rw8zjdsisw3pgccibmdwj9ry5p1451 client_pushes_test.go:97: Retrieved narinfo from S3:1452 StorePath: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientPushesUseOnePush1281427186/001/store/47ni8xpxp1ri38l8k54dyyd9ihmkdjz7-b1453 URL: nar/1kj33y9jbn3919nlzfz352k6rk6i02xanmcl3ckspwgr0rby8y76.nar.zst1454 Compression: zstd1455 NarHash: sha256:1kj33y9jbn3919nlzfz352k6rk6i02xanmcl3ckspwgr0rby8y761456 NarSize: 2561457 References: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientPushesUseOnePush1281427186/001/store/d6x8zy41f0kzlfhv9z90z6h98yjfnxvz-shared-dep1458 CA: text:sha256:047j5128ziy83xn6pbqsxpg4s1rw8zjdsisw3pgccibmdwj9ry5p14592026/10/10 19:42:38 INFO Received push request method=POST path=/api/pushes1460--- PASS: TestClientPushesUseOnePush (6.57s)1461=== CONT TestCreatePendingClosureRejectsOversizedNAR14622026/10/10 19:42:38 INFO Received uploads request method=POST path=/api/pending_closures1463--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1464=== CONT TestServerTLSConfig1465=== RUN TestServerTLSConfig/no_client_CA1466=== PAUSE TestServerTLSConfig/no_client_CA1467=== RUN TestServerTLSConfig/missing_CA_file1468=== PAUSE TestServerTLSConfig/missing_CA_file1469=== RUN TestServerTLSConfig/not_a_PEM_file1470=== PAUSE TestServerTLSConfig/not_a_PEM_file1471=== CONT TestCacheConfigHandlerMaxNarSize14722026/10/10 19:42:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14732026/10/10 19:42:38 INFO Uploading dn812gicfyzwdmn41nr7jg5saka0mhah-pinned-file.txt (128B)1474--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1475=== CONT TestClientIntegration14762026/10/10 19:42:38 WARN Failed to register uploaded object key=dn812gicfyzwdmn41nr7jg5saka0mhah.ls error="server returned 404: 404 page not found\n"14772026/10/10 19:42:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14782026/10/10 19:42:38 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14792026/10/10 19:42:38 INFO Signed narinfos id=1 count=114802026/10/10 19:42:38 INFO Uploading 1 narinfos14812026/10/10 19:42:38 INFO Received complete push request method=POST path=/api/pushes/1/complete14822026/10/10 19:42:38 WARN Failed to register uploaded object key=dn812gicfyzwdmn41nr7jg5saka0mhah.narinfo error="server returned 404: 404 page not found\n"14832026/10/10 19:42:38 INFO Completed push id=1 objects=3 duration=16.876208ms14842026/10/10 19:42:38 INFO Upload complete. (137ms)1485--- PASS: TestReadProxyContentNegotiation (5.45s)1486=== CONT TestGenerateLandingPage1487--- PASS: TestGenerateLandingPage (0.00s)1488=== CONT TestService_ReadAuthMiddleware14892026/10/10 19:42:38 INFO Received push request method=POST path=/api/pushes14902026/10/10 19:42:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14912026/10/10 19:42:38 INFO Uploading nprlq7lwl33rmmd6yvr097g7283gpifd-unpinned-file.txt (128B)14922026/10/10 19:42:38 WARN Failed to register uploaded object key=nprlq7lwl33rmmd6yvr097g7283gpifd.ls error="server returned 404: 404 page not found\n"14932026/10/10 19:42:38 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14942026/10/10 19:42:38 INFO Signed narinfos id=2 count=114952026/10/10 19:42:38 INFO Uploading 1 narinfos14962026/10/10 19:42:38 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"1497--- PASS: TestReadProxyOutlastsServerWriteTimeout (11.45s)1498=== CONT TestService_readinessHandler14992026/10/10 19:42:38 INFO Received complete push request method=POST path=/api/pushes/2/complete15002026/10/10 19:42:38 WARN Failed to register uploaded object key=nprlq7lwl33rmmd6yvr097g7283gpifd.narinfo error="server returned 404: 404 page not found\n"15012026/10/10 19:42:38 INFO Completed push id=2 objects=3 duration=902.916µs15022026/10/10 19:42:38 INFO Upload complete. (123ms)15032026/10/10 19:42:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures15042026/10/10 19:42:38 INFO Garbage collection started15052026/10/10 19:42:38 INFO Aborted multipart uploads count=0 kept=015062026/10/10 19:42:38 WARN Force mode enabled - objects will be deleted immediately without grace period1507--- PASS: TestReadProxyInvalidPath (5.15s)1508=== CONT TestService_AuthMiddleware_OIDC15092026/10/10 19:42:38 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=015102026/10/10 19:42:38 INFO Vacuumed table table=pending_closures15112026/10/10 19:42:38 INFO Vacuumed table table=pending_objects15122026/10/10 19:42:38 INFO Vacuumed table table=multipart_uploads15132026/10/10 19:42:38 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49521/oidc15142026/10/10 19:42:38 INFO Vacuumed table table=closures15152026/10/10 19:42:38 INFO Vacuumed table table=objects1516--- PASS: TestReadProxy404 (5.21s)1517=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1518--- PASS: TestReadProxyNarStreaming (4.87s)1519=== CONT TestClientErrorHandling1520=== RUN TestClientErrorHandling/InvalidStorePath1521=== PAUSE TestClientErrorHandling/InvalidStorePath1522=== RUN TestClientErrorHandling/InvalidAuthToken1523=== PAUSE TestClientErrorHandling/InvalidAuthToken1524=== RUN TestClientErrorHandling/ServerNotAvailable1525=== PAUSE TestClientErrorHandling/ServerNotAvailable1526=== CONT TestService_AuthMiddleware_MTLSProxyHeader1527=== NAME TestClientMultipleUploads1528 client_integration_test.go:358: Created store path 0: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientMultipleUploads955649448/001/store/vnia7dv77a9j6px22idrc3lrf7lpfnqd-test-file-0.txt1529 client_integration_test.go:358: Created store path 1: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientMultipleUploads955649448/001/store/pr2iq3sp5lbs3q83gsb7yr66m2jg0321-test-file-1.txt1530 client_integration_test.go:358: Created store path 2: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientMultipleUploads955649448/001/store/4n5jx8r7d2908z46skga5yybmz49sdyn-test-file-2.txt15312026/10/10 19:42:39 INFO Received push request method=POST path=/api/pushes15322026/10/10 19:42:39 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15332026/10/10 19:42:39 INFO Uploading pr2iq3sp5lbs3q83gsb7yr66m2jg0321-test-file-1.txt (160B)15342026/10/10 19:42:39 INFO Uploading 4n5jx8r7d2908z46skga5yybmz49sdyn-test-file-2.txt (160B)15352026/10/10 19:42:39 INFO Uploading vnia7dv77a9j6px22idrc3lrf7lpfnqd-test-file-0.txt (160B)15362026/10/10 19:42:39 WARN Failed to register uploaded object key=4n5jx8r7d2908z46skga5yybmz49sdyn.ls error="server returned 404: 404 page not found\n"15372026/10/10 19:42:39 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15382026/10/10 19:42:39 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15392026/10/10 19:42:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15402026/10/10 19:42:39 WARN Failed to register uploaded object key=vnia7dv77a9j6px22idrc3lrf7lpfnqd.ls error="server returned 404: 404 page not found\n"15412026/10/10 19:42:39 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15422026/10/10 19:42:39 WARN Failed to register uploaded object key=pr2iq3sp5lbs3q83gsb7yr66m2jg0321.ls error="server returned 404: 404 page not found\n"15432026/10/10 19:42:39 INFO Signed narinfos id=1 count=315442026/10/10 19:42:39 INFO Uploading 3 narinfos15452026/10/10 19:42:39 WARN Failed to register uploaded object key=vnia7dv77a9j6px22idrc3lrf7lpfnqd.narinfo error="server returned 404: 404 page not found\n"15462026/10/10 19:42:39 WARN Failed to register uploaded object key=4n5jx8r7d2908z46skga5yybmz49sdyn.narinfo error="server returned 404: 404 page not found\n"15472026/10/10 19:42:39 INFO Received complete push request method=POST path=/api/pushes/1/complete15482026/10/10 19:42:39 WARN Failed to register uploaded object key=pr2iq3sp5lbs3q83gsb7yr66m2jg0321.narinfo error="server returned 404: 404 page not found\n"15492026/10/10 19:42:39 INFO Completed push id=1 objects=9 duration=15.44125ms15502026/10/10 19:42:39 INFO Upload complete. (154ms)1551 client_integration_test.go:369: Uploaded 3 paths in 188.799875ms1552--- PASS: TestCacheStatsHandler (4.77s)1553=== CONT TestParseSingleRange1554=== RUN TestParseSingleRange/none1555=== PAUSE TestParseSingleRange/none1556=== RUN TestParseSingleRange/unknown_unit1557=== PAUSE TestParseSingleRange/unknown_unit1558=== RUN TestParseSingleRange/multi-range_ignored1559=== PAUSE TestParseSingleRange/multi-range_ignored1560=== RUN TestParseSingleRange/malformed_no_dash1561=== PAUSE TestParseSingleRange/malformed_no_dash1562=== RUN TestParseSingleRange/malformed_both_empty1563=== PAUSE TestParseSingleRange/malformed_both_empty1564=== RUN TestParseSingleRange/malformed_end_before_start1565=== PAUSE TestParseSingleRange/malformed_end_before_start1566=== RUN TestParseSingleRange/closed1567=== PAUSE TestParseSingleRange/closed1568=== RUN TestParseSingleRange/open-ended1569=== PAUSE TestParseSingleRange/open-ended1570=== RUN TestParseSingleRange/end_clamped_to_size1571=== PAUSE TestParseSingleRange/end_clamped_to_size1572=== RUN TestParseSingleRange/suffix1573=== PAUSE TestParseSingleRange/suffix1574=== RUN TestParseSingleRange/suffix_exceeds_size1575=== PAUSE TestParseSingleRange/suffix_exceeds_size1576=== RUN TestParseSingleRange/single_byte1577=== PAUSE TestParseSingleRange/single_byte1578=== RUN TestParseSingleRange/start_past_EOF1579=== PAUSE TestParseSingleRange/start_past_EOF1580=== RUN TestParseSingleRange/start_far_past_EOF1581=== PAUSE TestParseSingleRange/start_far_past_EOF1582=== CONT TestPresentNotReportedWhileGCDeletesClosure1583=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1584=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1585=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1586=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1587=== CONT TestGCTaskStore_DeduplicateSameParams1588--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1589=== CONT TestGracefulShutdownDrainsInflight15902026/10/10 19:42:39 INFO Starting HTTP server address=127.0.0.1:4954515912026/10/10 19:42:39 INFO Shutdown signal received, draining in-flight requests timeout=10s1592--- PASS: TestClientMultipleUploads (5.21s)1593=== CONT TestPushWaitsForSweepHoldingRow1594=== NAME TestClientWithDependencies1595 client_integration_test.go:613: Built derivation: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientWithDependencies3530212171/001/store/vizv7jx4f7ny7s6c7gj808nbd93mpm9n-test-script1596--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1597=== CONT TestGCTaskStore_StartNew1598--- PASS: TestGCTaskStore_StartNew (0.00s)1599=== CONT TestGCEndsOnShutdown1600=== RUN TestGCEndsOnShutdown/before_the_run1601=== PAUSE TestGCEndsOnShutdown/before_the_run1602=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1603=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1604=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1605=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1606=== CONT TestGCTaskStore_Fail1607--- PASS: TestGCTaskStore_Fail (0.00s)1608=== CONT TestCommitRacingPendingCleanupKeepsObjects1609=== NAME TestClientWithDependencies1610 client_integration_test.go:615: Found 1 dependencies (including self)1611--- PASS: TestReadProxyNarinfoAlreadyDecompressed (4.94s)1612=== CONT TestGCTaskStore_PhaseUpdates1613--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1614=== CONT TestGCTaskStore_GetReturnsLatest1615--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1616=== CONT TestGCTaskStore_GetEmpty1617--- PASS: TestGCTaskStore_GetEmpty (0.00s)1618=== CONT TestGCTaskStore_CompletedAllowsNewTask1619--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1620=== CONT TestGCTaskStore_ConflictDifferentParams1621--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1622=== CONT TestGetExistingObjectsLocksRows16232026/10/10 19:42:39 INFO Received push request method=POST path=/api/pushes16242026/10/10 19:42:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16252026/10/10 19:42:39 INFO Uploading vizv7jx4f7ny7s6c7gj808nbd93mpm9n-test-script (136B)16262026/10/10 19:42:39 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"16272026/10/10 19:42:39 WARN Failed to register uploaded object key=vizv7jx4f7ny7s6c7gj808nbd93mpm9n.ls error="server returned 404: 404 page not found\n"16282026/10/10 19:42:39 WARN Failed to register uploaded object key=log/hi2xjkc4208gmp1g5s19qnl1mqhmmkay-test-script.drv error="server returned 404: 404 page not found\n"16292026/10/10 19:42:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16302026/10/10 19:42:39 INFO Signed narinfos id=1 count=116312026/10/10 19:42:39 INFO Uploading 1 narinfos16322026/10/10 19:42:39 INFO Received complete push request method=POST path=/api/pushes/1/complete16332026/10/10 19:42:39 WARN Failed to register uploaded object key=vizv7jx4f7ny7s6c7gj808nbd93mpm9n.narinfo error="server returned 404: 404 page not found\n"16342026/10/10 19:42:39 INFO Completed push id=1 objects=4 duration=26.154042ms16352026/10/10 19:42:39 INFO Upload complete. (168ms)1636=== NAME TestClientWithDependencies1637 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientWithDependencies3530212171/001/store) requires matching store prefix1638--- PASS: TestClientWithDependencies (5.47s)1639=== CONT TestSweepRechecksPendingAfterLocking1640--- PASS: TestService_ReadScope_PublicByDefault (5.02s)1641=== CONT TestRegisterCompletedObjectNeedsPendingRow16422026/10/10 19:42:40 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1643--- PASS: TestReadProxyNarinfo (5.14s)1644=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows16452026/10/10 19:42:40 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=016462026/10/10 19:42:40 INFO Received create pin request method=POST path=/api/pins/myapp16472026/10/10 19:42:40 INFO Created/updated pin name=myapp store_path=/private/var/tb/7/scratch/fa1433502527f7cf/build/TestPinProtectsFromGC2558766644/001/store/dn812gicfyzwdmn41nr7jg5saka0mhah-pinned-file.txt narinfo_key=dn812gicfyzwdmn41nr7jg5saka0mhah.narinfo16482026/10/10 19:42:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures16492026/10/10 19:42:40 INFO Garbage collection started16502026/10/10 19:42:40 INFO Aborted multipart uploads count=0 kept=016512026/10/10 19:42:40 WARN Force mode enabled - objects will be deleted immediately without grace period16522026/10/10 19:42:40 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=016532026/10/10 19:42:40 INFO Vacuumed table table=pending_closures16542026/10/10 19:42:40 INFO Vacuumed table table=pending_objects16552026/10/10 19:42:40 INFO Vacuumed table table=multipart_uploads16562026/10/10 19:42:40 INFO Vacuumed table table=closures16572026/10/10 19:42:40 INFO Vacuumed table table=objects1658--- PASS: TestService_healthCheckHandler (5.05s)1659=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check16602026/10/10 19:42:40 INFO Received push request method=POST path=/api/pushes16612026/10/10 19:42:40 INFO Received complete push request method=POST path=/api/pushes/1/complete16622026/10/10 19:42:40 INFO Completed push id=1 objects=4 duration=29.165375ms16632026/10/10 19:42:40 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16642026/10/10 19:42:40 INFO Completed upload id=2 objects=2 duration=1.186166ms1665--- PASS: TestMetricsCommit (5.15s)1666=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16672026/10/10 19:42:40 INFO Received uploads request method=POST path=/1668=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16692026/10/10 19:42:40 INFO Received complete multipart upload request method=POST path=/1670=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16712026/10/10 19:42:40 INFO Received request for more parts method=POST path=/1672=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16732026/10/10 19:42:40 INFO Received uploads request method=POST path=/1674--- PASS: TestUploadHandlersRejectInvalidKeys (0.05s)1675 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1676 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1677 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1678 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1679=== CONT TestIsValidUploadKey/narinfo1680=== CONT TestProxyWriteTimeout/narinfo1681=== CONT TestIsValidUploadKey/build_log_equals1682=== CONT TestIsValidUploadKey/unknown_type1683=== CONT TestIsValidUploadKey/empty_key1684=== CONT TestIsValidUploadKey/absolute1685=== CONT TestIsValidUploadKey/traversal_nar1686=== CONT TestIsValidUploadKey/traversal1687=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1688=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1689=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1690=== CONT TestIsValidUploadKey/index.html1691=== CONT TestIsValidUploadKey/nix-cache-info1692=== CONT TestIsValidUploadKey/realisation_plus_in_output1693=== CONT TestIsValidUploadKey/realisation1694=== CONT TestIsValidUploadKey/nar_zst1695=== CONT TestIsValidUploadKey/build_log_question_mark1696=== CONT TestIsValidUploadKey/build_log_plus_in_name1697=== CONT TestIsValidUploadKey/build_log_home-manager_file1698=== CONT TestIsValidUploadKey/build_log1699=== CONT TestIsValidUploadKey/listing1700=== CONT TestIsValidUploadKey/nar_plain1701=== CONT TestIsValidUploadKey/nar_xz1702--- PASS: TestIsValidUploadKey (0.05s)1703 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1704 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1705 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1706 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1707 --- PASS: TestIsValidUploadKey/absolute (0.00s)1708 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1709 --- PASS: TestIsValidUploadKey/traversal (0.00s)1710 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1711 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1712 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1713 --- PASS: TestIsValidUploadKey/index.html (0.00s)1714 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1715 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1716 --- PASS: TestIsValidUploadKey/realisation (0.00s)1717 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1718 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1719 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1720 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1721 --- PASS: TestIsValidUploadKey/build_log (0.00s)1722 --- PASS: TestIsValidUploadKey/listing (0.00s)1723 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1724 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1725=== CONT TestProxyWriteTimeout/10_GiB_nar1726=== CONT TestPendingClosureWriteTimeout/empty1727=== CONT TestProxyWriteTimeout/1_GiB_nar1728=== CONT TestProxyWriteTimeout/unknown_size1729--- PASS: TestProxyWriteTimeout (0.05s)1730 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1731 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1732 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1733 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1734=== CONT TestPendingClosureWriteTimeout/670k_objects1735=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline17362026/10/10 19:42:40 WARN mTLS auth: subject not in bound subjects subject="CN=reader"17372026/10/10 19:42:40 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1738--- PASS: TestService_NativeMTLS (5.30s)1739=== CONT TestPendingClosureWriteTimeout/400_objects1740=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17412026/10/10 19:42:40 INFO Received uploads request method=POST path=/1742=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17432026/10/10 19:42:41 INFO Received request for more parts method=POST path=/1744=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17452026/10/10 19:42:41 INFO Received complete multipart upload request method=POST path=/1746--- PASS: TestUploadHandlersRejectOversizedBody (0.08s)1747 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.30s)1748 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1749 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1750=== CONT TestResolveDBConnectionString/flag_wins1751=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1752=== CONT TestResolveDBConnectionString/nothing_configured1753=== CONT TestResolveDBConnectionString/missing_file_is_an_error1754=== CONT TestResolveDBConnectionString/file_when_flag_empty1755=== CONT TestPush_RejectsBadRequests/no_objects17562026/10/10 19:42:41 INFO Received push request method=POST path=/api/pushes1757=== CONT TestPush_RejectsBadRequests/root_not_in_objects17582026/10/10 19:42:41 INFO Received push request method=POST path=/api/pushes1759--- PASS: TestResolveDBConnectionString (0.03s)1760 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1761 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1762 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1763 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1764 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1765=== CONT TestPush_RejectsBadRequests/bad_root17662026/10/10 19:42:41 INFO Received push request method=POST path=/api/pushes1767=== CONT TestPush_RejectsBadRequests/no_roots17682026/10/10 19:42:41 INFO Received push request method=POST path=/api/pushes1769=== CONT TestCacheConfigHandler/full_config,_no_issuer1770--- PASS: TestPush_RejectsBadRequests (7.20s)1771 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1772 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1773 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1774 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1775=== CONT TestCacheConfigHandler/no_signing_keys1776=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1777=== CONT TestCacheConfigHandler/no_cache_url_configured1778--- PASS: TestCacheConfigHandler (0.00s)1779 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1780 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1781 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1782 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1783=== CONT TestIsValidCachePath/narinfo1784=== CONT TestIsValidCachePath/index.html1785=== CONT TestIsValidCachePath/short_hash1786=== CONT TestIsValidCachePath/wrong_extension1787=== CONT TestIsValidCachePath/leading_slash1788=== CONT TestIsValidCachePath/empty1789=== CONT TestIsValidCachePath/random_path1790=== CONT TestIsValidCachePath/invalid_char_u1791=== CONT TestIsValidCachePath/invalid_char_e1792=== CONT TestIsValidCachePath/traversal_in_middle1793=== CONT TestIsValidCachePath/traversal_parent1794=== CONT TestIsValidCachePath/nar_uncompressed1795=== CONT TestIsValidCachePath/nix-cache-info1796=== CONT TestIsValidCachePath/realisation1797=== CONT TestIsValidCachePath/log1798=== CONT TestIsValidCachePath/ls1799=== CONT TestIsValidCachePath/nar_bz21800=== CONT TestIsValidCachePath/nar_zst1801=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1802=== CONT TestIsValidCachePath/nar_xz1803--- PASS: TestIsValidCachePath (0.01s)1804 --- PASS: TestIsValidCachePath/narinfo (0.00s)1805 --- PASS: TestIsValidCachePath/index.html (0.00s)1806 --- PASS: TestIsValidCachePath/short_hash (0.00s)1807 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1808 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1809 --- PASS: TestIsValidCachePath/empty (0.00s)1810 --- PASS: TestIsValidCachePath/random_path (0.00s)1811 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1812 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1813 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1814 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1815 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1816 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1817 --- PASS: TestIsValidCachePath/realisation (0.00s)1818 --- PASS: TestIsValidCachePath/log (0.00s)1819 --- PASS: TestIsValidCachePath/ls (0.00s)1820 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1821 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1822 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1823 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1824=== CONT TestService_RequireScope_OIDC/builder_may_write1825=== CONT TestService_RequireScope_OIDC/reader_may_read1826=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1827=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read18282026/10/10 19:42:41 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]1829=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1830=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1831=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1832=== CONT TestService_RequireScope_OIDC/writer_implies_read1833=== CONT TestService_RequireScope_OIDC/reader_may_not_write1834=== CONT TestService_RequireScope_OIDC/static_token_may_write1835=== CONT TestService_RequireScope_OIDC/static_token_may_admin1836=== CONT TestService_RequireScope_OIDC/ops_may_admin1837=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1838=== CONT TestService_RequireScope_OIDC/ops_may_not_write1839=== CONT TestServerTLSConfig/no_client_CA1840=== CONT TestServerTLSConfig/not_a_PEM_file1841--- PASS: TestService_RequireScope_OIDC (6.27s)1842 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1843 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1844 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1845 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1846 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1847 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1848 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1849 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1850 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1851 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1852 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1853 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1854 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1855 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1856=== CONT TestServerTLSConfig/missing_CA_file1857--- PASS: TestServerTLSConfig (0.00s)1858 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1859 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1860 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1861=== CONT TestClientErrorHandling/InvalidStorePath1862--- PASS: TestObjectStatsTrigger (5.23s)1863=== CONT TestClientErrorHandling/ServerNotAvailable1864=== NAME TestOrphanedObjectsGC1865 orphaned_objects_gc_test.go:287: GC Test Summary:1866 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1867 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1868 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1869 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1870 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1871--- PASS: TestOrphanedObjectsGC (5.80s)1872=== CONT TestClientErrorHandling/InvalidAuthToken18732026/10/10 19:42:41 INFO Received uploads request method=POST path=/api/pending_closures18742026/10/10 19:42:41 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18752026/10/10 19:42:41 INFO Received uploads request method=POST path=/api/pending_closures18762026/10/10 19:42:41 INFO Received cleanup request method=DELETE path=/api/pending_closures18772026/10/10 19:42:41 WARN Request failed, retrying attempt=2 backoff=218.031937ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1878--- PASS: TestMetricsInventory (5.12s)1879=== CONT TestParseSingleRange/none1880=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale18812026/10/10 19:42:42 INFO Received uploads request method=POST path=/api/pending_closures18822026/10/10 19:42:42 WARN Request failed, retrying attempt=3 backoff=432.992253ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1883--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (4.51s)1884=== CONT TestParseSingleRange/start_far_past_EOF1885=== CONT TestParseSingleRange/start_past_EOF1886=== CONT TestParseSingleRange/single_byte1887=== CONT TestParseSingleRange/suffix_exceeds_size1888=== CONT TestParseSingleRange/suffix1889=== CONT TestParseSingleRange/end_clamped_to_size1890=== CONT TestParseSingleRange/open-ended1891=== CONT TestParseSingleRange/closed1892=== CONT TestParseSingleRange/malformed_end_before_start1893=== CONT TestParseSingleRange/malformed_both_empty1894=== CONT TestParseSingleRange/malformed_no_dash1895=== CONT TestParseSingleRange/multi-range_ignored1896=== CONT TestParseSingleRange/unknown_unit1897--- PASS: TestParseSingleRange (0.00s)1898 --- PASS: TestParseSingleRange/none (0.00s)1899 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1900 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1901 --- PASS: TestParseSingleRange/single_byte (0.00s)1902 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1903 --- PASS: TestParseSingleRange/suffix (0.00s)1904 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1905 --- PASS: TestParseSingleRange/open-ended (0.00s)1906 --- PASS: TestParseSingleRange/closed (0.00s)1907 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1908 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1909 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1910 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1911 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1912=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1913=== NAME TestPinProtectsFromGC1914 client_integration_test.go:840: Pin successfully protected closure from garbage collection1915=== NAME TestNARDeduplicationMetadataUploadBug1916 metadata_upload_test.go:48: First store path: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestNARDeduplicationMetadataUploadBug2343919800/001/store/zm15lmfinnvabgfy6r75n9m08xwa98m5-file1.txt1917--- PASS: TestPinProtectsFromGC (10.00s)1918=== CONT TestGCEndsOnShutdown/before_the_run19192026/10/10 19:42:42 INFO Received uploads request method=POST path=/api/pending_closures19202026/10/10 19:42:42 INFO Received push request method=POST path=/api/pushes19212026/10/10 19:42:42 WARN Request failed, retrying attempt=4 backoff=813.232855ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19222026/10/10 19:42:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19232026/10/10 19:42:42 INFO Uploading zm15lmfinnvabgfy6r75n9m08xwa98m5-file1.txt (160B)19242026/10/10 19:42:42 WARN Failed to register uploaded object key=zm15lmfinnvabgfy6r75n9m08xwa98m5.ls error="server returned 404: 404 page not found\n"19252026/10/10 19:42:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19262026/10/10 19:42:42 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"19272026/10/10 19:42:42 INFO Signed narinfos id=1 count=119282026/10/10 19:42:42 INFO Uploading 1 narinfos19292026/10/10 19:42:42 INFO Received complete push request method=POST path=/api/pushes/1/complete19302026/10/10 19:42:42 WARN Failed to register uploaded object key=zm15lmfinnvabgfy6r75n9m08xwa98m5.narinfo error="server returned 404: 404 page not found\n"19312026/10/10 19:42:42 INFO Completed push id=1 objects=3 duration=10.937541ms19322026/10/10 19:42:42 INFO Upload complete. (135ms)1933=== NAME TestNARDeduplicationMetadataUploadBug1934 metadata_upload_test.go:54: Retrieved narinfo from S3:1935 StorePath: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestNARDeduplicationMetadataUploadBug2343919800/001/store/zm15lmfinnvabgfy6r75n9m08xwa98m5-file1.txt1936 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1937 Compression: zstd1938 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1939 NarSize: 1601940 References: 1941 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1942 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1943 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1944 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}19452026/10/10 19:42:42 INFO Received cleanup request method=DELETE path=/api/pending_closures19462026/10/10 19:42:42 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket79/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""19472026/10/10 19:42:42 INFO Aborted multipart uploads count=0 kept=119482026/10/10 19:42:42 INFO Received cleanup request method=DELETE path=/api/pending_closures19492026/10/10 19:42:42 INFO Aborted multipart uploads count=1 kept=01950--- PASS: TestMultipartCleanup (4.67s)1951=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1952=== NAME TestNARDeduplicationMetadataUploadBug1953 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/7/scratch/fa1433502527f7cf/build/TestNARDeduplicationMetadataUploadBug2343919800/001/store/pvj75dj14dnyl61qc5w5ykfm24cqainc-file2.txt19542026/10/10 19:42:42 INFO Received push request method=POST path=/api/pushes19552026/10/10 19:42:42 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1956=== NAME TestClientIntegration19572026/10/10 19:42:42 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign1958 client_integration_test.go:286: Created store path: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientIntegration588737540/002/store/rkbaxnhi5anbv60cc2r5h5s51yym56qy-test-file.txt19592026/10/10 19:42:42 WARN Failed to register uploaded object key=pvj75dj14dnyl61qc5w5ykfm24cqainc.ls error="server returned 404: 404 page not found\n"19602026/10/10 19:42:42 INFO Signed narinfos id=2 count=119612026/10/10 19:42:42 INFO Uploading 1 narinfos19622026/10/10 19:42:42 INFO Received complete push request method=POST path=/api/pushes/2/complete19632026/10/10 19:42:42 WARN Failed to register uploaded object key=pvj75dj14dnyl61qc5w5ykfm24cqainc.narinfo error="server returned 404: 404 page not found\n"19642026/10/10 19:42:42 INFO Completed push id=2 objects=3 duration=828.458µs19652026/10/10 19:42:42 INFO Upload complete. (86ms)1966=== NAME TestNARDeduplicationMetadataUploadBug1967 metadata_upload_test.go:76: Retrieved narinfo from S3:1968 StorePath: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestNARDeduplicationMetadataUploadBug2343919800/001/store/pvj75dj14dnyl61qc5w5ykfm24cqainc-file2.txt1969 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1970 Compression: zstd1971 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1972 NarSize: 1601973 References: 1974 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1975 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1976 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1977 {"version":1,"root":{"type":"regular","size":44}}1978--- PASS: TestNARDeduplicationMetadataUploadBug (5.12s)1979=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19802026/10/10 19:42:42 WARN readiness check failed error="closed pool"1981--- PASS: TestService_readinessHandler (4.58s)19822026/10/10 19:42:42 INFO Received push request method=POST path=/api/pushes19832026/10/10 19:42:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19842026/10/10 19:42:42 INFO Uploading rkbaxnhi5anbv60cc2r5h5s51yym56qy-test-file.txt (152B)19852026/10/10 19:42:43 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19862026/10/10 19:42:43 WARN Failed to register uploaded object key=rkbaxnhi5anbv60cc2r5h5s51yym56qy.ls error="server returned 404: 404 page not found\n"19872026/10/10 19:42:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19882026/10/10 19:42:43 INFO Signed narinfos id=1 count=119892026/10/10 19:42:43 INFO Uploading 1 narinfos19902026/10/10 19:42:43 INFO Received complete push request method=POST path=/api/pushes/1/complete19912026/10/10 19:42:43 WARN Failed to register uploaded object key=rkbaxnhi5anbv60cc2r5h5s51yym56qy.narinfo error="server returned 404: 404 page not found\n"19922026/10/10 19:42:43 INFO Completed push id=1 objects=3 duration=24.244833ms19932026/10/10 19:42:43 INFO Upload complete. (147ms)19942026/10/10 19:42:43 INFO All 1 paths already cached1995=== NAME TestClientIntegration1996 client_integration_test.go:312: Retrieved narinfo from S3:1997 StorePath: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestClientIntegration588737540/002/store/rkbaxnhi5anbv60cc2r5h5s51yym56qy-test-file.txt1998 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1999 Compression: zstd2000 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12001 NarSize: 1522002 References: 2003 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12004 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2005 client_integration_test.go:313: Decompressed .ls content (64 bytes):2006 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2007 client_integration_test.go:316: Testing garbage collection...20082026/10/10 19:42:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures20092026/10/10 19:42:43 INFO Garbage collection started20102026/10/10 19:42:43 INFO Aborted multipart uploads count=0 kept=02011--- PASS: TestService_ReadAuthMiddleware (4.84s)20122026/10/10 19:42:43 WARN Force mode enabled - objects will be deleted immediately without grace period20132026/10/10 19:42:43 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=020142026/10/10 19:42:43 INFO Vacuumed table table=pending_closures20152026/10/10 19:42:43 INFO Vacuumed table table=pending_objects20162026/10/10 19:42:43 INFO Vacuumed table table=multipart_uploads20172026/10/10 19:42:43 INFO Vacuumed table table=closures20182026/10/10 19:42:43 INFO Vacuumed table table=objects2019=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2020=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2021=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2022=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2023=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2024=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2025=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2026=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2027=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2028=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected2029=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20302026/10/10 19:42:43 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]2031=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured20322026/10/10 19:42:43 WARN Authentication failed token_preview=eyJhbGciOi...rPymUu2QAw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2033--- PASS: TestService_AuthMiddleware_OIDC (4.86s)2034 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2035 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2036 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2037 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)20382026/10/10 19:42:43 WARN Request failed, retrying attempt=5 backoff=1.724257376s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20392026/10/10 19:42:43 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20402026/10/10 19:42:43 WARN mTLS auth: bound subjects configured but subject DN unavailable20412026/10/10 19:42:43 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2042--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (4.77s)2043--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (4.74s)20442026/10/10 19:42:43 INFO Received uploads request method=POST path=/api/pending_closures20452026/10/10 19:42:44 INFO Aborted multipart uploads count=0 kept=020462026/10/10 19:42:44 WARN Force mode enabled - objects will be deleted immediately without grace period20472026/10/10 19:42:44 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=020482026/10/10 19:42:44 INFO Vacuumed table table=pending_closures20492026/10/10 19:42:44 INFO Vacuumed table table=pending_objects20502026/10/10 19:42:44 INFO Vacuumed table table=multipart_uploads20512026/10/10 19:42:44 INFO Vacuumed table table=closures20522026/10/10 19:42:44 INFO Vacuumed table table=objects2053--- PASS: TestCommitRacingPendingCleanupKeepsObjects (4.67s)2054--- PASS: TestGetExistingObjectsLocksRows (4.59s)2055--- PASS: TestPushWaitsForSweepHoldingRow (4.76s)20562026/10/10 19:42:44 INFO Aborted multipart uploads count=0 kept=020572026/10/10 19:42:44 WARN Force mode enabled - objects will be deleted immediately without grace period20582026/10/10 19:42:44 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=020592026/10/10 19:42:44 INFO Vacuumed table table=pending_closures20602026/10/10 19:42:44 INFO Vacuumed table table=pending_objects20612026/10/10 19:42:44 INFO Vacuumed table table=multipart_uploads20622026/10/10 19:42:44 INFO Vacuumed table table=closures20632026/10/10 19:42:44 INFO Vacuumed table table=objects2064--- PASS: TestSweepRechecksPendingAfterLocking (4.72s)2065--- PASS: TestRegisterCompletedObjectNeedsPendingRow (4.71s)20662026/10/10 19:42:45 INFO Received uploads request method=POST path=/api/pending_closures20672026/10/10 19:42:45 INFO Aborted multipart uploads count=0 kept=020682026/10/10 19:42:45 WARN Force mode enabled - objects will be deleted immediately without grace period20692026/10/10 19:42:45 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02070=== NAME TestClientIntegration2071 client_integration_test.go:323: Objects in database after GC:2072 client_integration_test.go:323: Successfully deleted all objects with GC --force20732026/10/10 19:42:45 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=020742026/10/10 19:42:45 INFO Vacuumed table table=pending_closures20752026/10/10 19:42:45 INFO Vacuumed table table=pending_objects20762026/10/10 19:42:45 INFO Vacuumed table table=multipart_uploads20772026/10/10 19:42:45 INFO Vacuumed table table=closures20782026/10/10 19:42:45 INFO Vacuumed table table=objects2079--- PASS: TestClientIntegration (7.04s)20802026/10/10 19:42:45 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20812026/10/10 19:42:45 INFO Received uploads request method=POST path=/api/pending_closures20822026/10/10 19:42:45 WARN Request failed, retrying attempt=2 backoff=197.691472ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20832026/10/10 19:42:45 INFO Aborted multipart uploads count=0 kept=020842026/10/10 19:42:45 WARN Force mode enabled - objects will be deleted immediately without grace period20852026/10/10 19:42:45 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=020862026/10/10 19:42:45 INFO Vacuumed table table=pending_closures20872026/10/10 19:42:45 INFO Vacuumed table table=pending_objects20882026/10/10 19:42:45 INFO Vacuumed table table=multipart_uploads20892026/10/10 19:42:45 INFO Vacuumed table table=closures20902026-10-10 19:42:45.409 UTC [19432] LOG: checkpoint starting: wal20912026/10/10 19:42:45 INFO Vacuumed table table=objects2092--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2093 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (4.85s)2094 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (4.93s)20952026/10/10 19:42:45 INFO Received uploads request method=POST path=/api/pending_closures20962026/10/10 19:42:45 WARN Request failed, retrying attempt=3 backoff=366.621657ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20972026/10/10 19:42:45 WARN Request failed, retrying attempt=4 backoff=875.504924ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2098--- PASS: TestObjectStatsLargeCommit (9.84s)20992026/10/10 19:42:46 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21002026/10/10 19:42:46 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2101--- PASS: TestPendingClosureWriteTimeout (0.05s)2102 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2103 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2104 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2105 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (5.48s)21062026/10/10 19:42:46 INFO Aborted multipart uploads count=0 kept=021072026/10/10 19:42:46 WARN Force mode enabled - objects will be deleted immediately without grace period21082026-10-10 19:42:46.770 UTC [19954] ERROR: canceling statement due to user request21092026-10-10 19:42:46.770 UTC [19954] STATEMENT: -- name: MarkStaleObjects :execrows2110 WITH RECURSIVE ct AS (2111 SELECT timezone('UTC', now()) AS now2112 ),2113 closure_reach AS (2114 -- Start with all closure keys2115 SELECT o.key, o.refs2116 FROM objects o2117 INNER JOIN closures c ON o.key = c.key2118 UNION2119 -- Recursively add all referenced objects2120 SELECT o.key, o.refs2121 FROM objects o2122 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2123 ),2124 reachable_objects AS (2125 SELECT DISTINCT key FROM closure_reach2126 ),2127 stale_objects AS (2128 SELECT o.key2129 FROM objects AS o, ct2130 WHERE2131 NOT EXISTS (2132 SELECT 12133 FROM reachable_objects ro2134 WHERE ro.key = o.key2135 )2136 AND NOT EXISTS (2137 SELECT 12138 FROM pending_objects AS po2139 WHERE po.key = o.key2140 )2141 AND o.deleted_at IS NULL -- Only mark fresh objects2142 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2143 FOR UPDATE2144 )2145 UPDATE objects2146 SET2147 deleted_at = ct.now,2148 first_deleted_at = COALESCE(first_deleted_at, ct.now)2149 FROM stale_objects, ct2150 WHERE objects.key = stale_objects.key2151 2152--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2153 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (4.61s)2154 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (4.50s)21552026/10/10 19:42:46 WARN Request failed, retrying attempt=5 backoff=1.521632858s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21562026/10/10 19:42:46 INFO Aborted multipart uploads count=0 kept=021572026/10/10 19:42:46 WARN Force mode enabled - objects will be deleted immediately without grace period21582026/10/10 19:42:46 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:49346/bucket100/?delete=\": context canceled"2159--- PASS: TestGCEndsOnShutdown (0.00s)2160 --- PASS: TestGCEndsOnShutdown/before_the_run (3.98s)2161 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (4.03s)2162 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (4.02s)21632026/10/10 19:42:47 INFO Aborted multipart uploads count=1 kept=021642026/10/10 19:42:47 INFO Received cleanup request method=DELETE path=/api/pending_closures21652026/10/10 19:42:47 INFO Aborted multipart uploads count=1 kept=02166--- PASS: TestPendingCleanupUsesOneCutoff (11.34s)21672026/10/10 19:42:48 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 127.0.0.1:19999: connect: connection refused"21682026/10/10 19:42:48 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21692026/10/10 19:42:48 WARN Request failed, retrying attempt=2 backoff=218.697175ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21702026/10/10 19:42:48 WARN Request failed, retrying attempt=3 backoff=389.557944ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21712026/10/10 19:42:49 WARN Request failed, retrying attempt=4 backoff=831.54267ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21722026/10/10 19:42:49 WARN Request failed, retrying attempt=5 backoff=1.74151547s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21732026/10/10 19:42:51 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21742026/10/10 19:42:51 WARN Request failed, retrying attempt=2 backoff=212.764893ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21752026/10/10 19:42:51 WARN Request failed, retrying attempt=3 backoff=429.530726ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21762026/10/10 19:42:52 WARN Request failed, retrying attempt=4 backoff=779.602549ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21772026/10/10 19:42:53 WARN Request failed, retrying attempt=5 backoff=1.485961833s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2178--- PASS: TestClientErrorHandling (0.01s)2179 --- PASS: TestClientErrorHandling/InvalidStorePath (4.52s)2180 --- PASS: TestClientErrorHandling/InvalidAuthToken (4.46s)2181 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.01s)2182PASS2183{"timestamp":"2026-10-10T19:42:54.660658Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:49400","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(4)"}21842026-10-10 19:42:54.802 UTC [19427] LOG: received smart shutdown request21852026-10-10 19:42:54.803 UTC [19427] LOG: background worker "logical replication launcher" (PID 19437) exited with exit code 121862026-10-10 19:42:56.012 UTC [19432] LOG: checkpoint complete: wrote 12570 buffers (76.7%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=9.882 s, sync=0.633 s, total=10.604 s; sync files=34045, longest=0.001 s, average=0.001 s; distance=533177 kB, estimate=533177 kB; lsn=0/22C83A20, redo lsn=0/2203B52821872026-10-10 19:42:56.014 UTC [19432] LOG: shutting down21882026-10-10 19:42:56.014 UTC [19432] LOG: checkpoint starting: shutdown immediate21892026-10-10 19:42:56.017 UTC [19432] LOG: checkpoint complete: wrote 242 buffers (1.5%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.002 s, total=0.004 s; sync files=41, longest=0.001 s, average=0.001 s; distance=12577 kB, estimate=481117 kB; lsn=0/22C83A98, redo lsn=0/22C83A9821902026-10-10 19:42:56.022 UTC [19427] LOG: database system is shut down2191Running OIDC tests...2192=== RUN TestAudienceForIssuer2193=== PAUSE TestAudienceForIssuer2194=== RUN TestGlobMatch2195=== PAUSE TestGlobMatch2196=== RUN TestValidateToken_ValidToken2197=== PAUSE TestValidateToken_ValidToken2198=== RUN TestValidateToken_WrongAudience2199=== PAUSE TestValidateToken_WrongAudience2200=== RUN TestValidateToken_Expired2201=== PAUSE TestValidateToken_Expired2202=== RUN TestValidateToken_BoundClaimsMismatch2203=== PAUSE TestValidateToken_BoundClaimsMismatch2204=== RUN TestValidateToken_BoundSubjectMismatch2205=== PAUSE TestValidateToken_BoundSubjectMismatch2206=== RUN TestValidateToken_MultipleProviders2207=== PAUSE TestValidateToken_MultipleProviders2208=== RUN TestValidateToken_NoMatchingProvider2209=== PAUSE TestValidateToken_NoMatchingProvider2210=== RUN TestValidateToken_KubernetesServiceAccount2211=== PAUSE TestValidateToken_KubernetesServiceAccount2212=== RUN TestNewValidator_KubernetesRequiresCA2213=== PAUSE TestNewValidator_KubernetesRequiresCA2214=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2215=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2216=== RUN TestPins_ReservedForMatchingRule2217=== PAUSE TestPins_ReservedForMatchingRule2218=== RUN TestPins_TopLevelShorthand2219=== PAUSE TestPins_TopLevelShorthand2220=== RUN TestPins_ConfigValidation2221=== PAUSE TestPins_ConfigValidation2222=== RUN TestScopes_LegacyProviderDefaultsToWrite2223=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2224=== RUN TestScopes_Rules2225=== PAUSE TestScopes_Rules2226=== RUN TestScopes_ConfigValidation2227=== PAUSE TestScopes_ConfigValidation2228=== CONT TestAudienceForIssuer2229--- PASS: TestAudienceForIssuer (0.00s)2230=== CONT TestNewValidator_KubernetesRequiresCA2231=== CONT TestPins_ReservedForMatchingRule2232=== CONT TestPins_TopLevelShorthand2233=== CONT TestScopes_LegacyProviderDefaultsToWrite2234=== CONT TestScopes_ConfigValidation2235=== CONT TestScopes_Rules2236=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2237=== CONT TestValidateToken_BoundClaimsMismatch2238=== CONT TestValidateToken_KubernetesServiceAccount2239--- PASS: TestScopes_ConfigValidation (0.01s)2240=== CONT TestValidateToken_NoMatchingProvider2241=== CONT TestValidateToken_MultipleProviders2242=== CONT TestValidateToken_BoundSubjectMismatch2243=== CONT TestValidateToken_WrongAudience2244=== CONT TestValidateToken_Expired2245=== CONT TestPins_ConfigValidation2246--- PASS: TestPins_ConfigValidation (0.00s)2247=== CONT TestValidateToken_ValidToken2248=== CONT TestGlobMatch2249=== RUN TestGlobMatch/foo_foo2250=== PAUSE TestGlobMatch/foo_foo2251=== RUN TestGlobMatch/foo_bar2252=== PAUSE TestGlobMatch/foo_bar2253=== RUN TestGlobMatch/*_2254=== PAUSE TestGlobMatch/*_2255=== RUN TestGlobMatch/*_anything2256=== PAUSE TestGlobMatch/*_anything2257=== RUN TestGlobMatch/foo*_foo2258=== PAUSE TestGlobMatch/foo*_foo2259=== RUN TestGlobMatch/foo*_foobar2260=== PAUSE TestGlobMatch/foo*_foobar2261=== RUN TestGlobMatch/foo*_bar2262=== PAUSE TestGlobMatch/foo*_bar2263=== RUN TestGlobMatch/*bar_bar2264=== PAUSE TestGlobMatch/*bar_bar2265=== RUN TestGlobMatch/*bar_foobar2266=== PAUSE TestGlobMatch/*bar_foobar2267=== RUN TestGlobMatch/*bar_foo2268=== PAUSE TestGlobMatch/*bar_foo2269=== RUN TestGlobMatch/foo*bar_foobar2270=== PAUSE TestGlobMatch/foo*bar_foobar2271=== RUN TestGlobMatch/foo*bar_foo123bar2272=== PAUSE TestGlobMatch/foo*bar_foo123bar2273=== RUN TestGlobMatch/foo*bar_foobarbaz2274=== PAUSE TestGlobMatch/foo*bar_foobarbaz2275=== RUN TestGlobMatch/*/*_foo/bar2276=== PAUSE TestGlobMatch/*/*_foo/bar2277=== RUN TestGlobMatch/*/*_foo2278=== PAUSE TestGlobMatch/*/*_foo2279=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2280=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2281=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02282=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02283=== RUN TestGlobMatch/refs/*/main_refs/heads/main2284=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2285=== RUN TestGlobMatch/fo?_foo2286=== PAUSE TestGlobMatch/fo?_foo2287=== RUN TestGlobMatch/fo?_fo2288=== PAUSE TestGlobMatch/fo?_fo2289=== RUN TestGlobMatch/fo?_fooo2290=== PAUSE TestGlobMatch/fo?_fooo2291=== RUN TestGlobMatch/?oo_foo2292=== PAUSE TestGlobMatch/?oo_foo2293=== RUN TestGlobMatch/?oo_boo2294=== PAUSE TestGlobMatch/?oo_boo2295=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2296=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2297=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2298=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2299=== CONT TestGlobMatch/foo_foo2300=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2301=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2302=== CONT TestGlobMatch/?oo_boo2303=== CONT TestGlobMatch/?oo_foo2304=== CONT TestGlobMatch/fo?_fooo2305=== CONT TestGlobMatch/fo?_fo2306=== CONT TestGlobMatch/fo?_foo2307=== CONT TestGlobMatch/refs/*/main_refs/heads/main2308=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02309=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2310=== CONT TestGlobMatch/*/*_foo2311=== CONT TestGlobMatch/*/*_foo/bar2312=== CONT TestGlobMatch/foo*bar_foobarbaz2313=== CONT TestGlobMatch/foo*bar_foo123bar2314=== CONT TestGlobMatch/foo*bar_foobar2315=== CONT TestGlobMatch/*bar_foo2316=== CONT TestGlobMatch/*bar_foobar2317=== CONT TestGlobMatch/*bar_bar2318=== CONT TestGlobMatch/foo*_bar2319=== CONT TestGlobMatch/foo*_foobar2320=== CONT TestGlobMatch/foo*_foo2321=== CONT TestGlobMatch/*_anything2322=== CONT TestGlobMatch/*_2323=== CONT TestGlobMatch/foo_bar2324--- PASS: TestGlobMatch (0.00s)2325 --- PASS: TestGlobMatch/foo_foo (0.00s)2326 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2327 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2328 --- PASS: TestGlobMatch/?oo_boo (0.00s)2329 --- PASS: TestGlobMatch/?oo_foo (0.00s)2330 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2331 --- PASS: TestGlobMatch/fo?_fo (0.00s)2332 --- PASS: TestGlobMatch/fo?_foo (0.00s)2333 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2334 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2335 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2336 --- PASS: TestGlobMatch/*/*_foo (0.00s)2337 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2338 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2339 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2340 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2341 --- PASS: TestGlobMatch/*bar_foo (0.00s)2342 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2343 --- PASS: TestGlobMatch/*bar_bar (0.00s)2344 --- PASS: TestGlobMatch/foo*_bar (0.00s)2345 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2346 --- PASS: TestGlobMatch/foo*_foo (0.00s)2347 --- PASS: TestGlobMatch/*_anything (0.00s)2348 --- PASS: TestGlobMatch/*_ (0.00s)2349 --- PASS: TestGlobMatch/foo_bar (0.00s)23502026/10/10 19:42:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49668/oidc23512026/10/10 19:42:57 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232352--- PASS: TestPins_TopLevelShorthand (0.07s)23532026/10/10 19:42:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49673/oidc23542026/10/10 19:42:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49676/oidc2355--- PASS: TestValidateToken_BoundSubjectMismatch (0.08s)2356--- PASS: TestPins_ReservedForMatchingRule (0.09s)2357--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.09s)23582026/10/10 19:42:57 http: TLS handshake error from 127.0.0.1:49675: read tcp 127.0.0.1:49674->127.0.0.1:49675: use of closed network connection2359--- PASS: TestNewValidator_KubernetesRequiresCA (0.10s)23602026/10/10 19:42:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49680/oidc2361--- PASS: TestValidateToken_WrongAudience (0.09s)23622026/10/10 19:42:57 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:496822363--- PASS: TestValidateToken_KubernetesServiceAccount (0.11s)23642026/10/10 19:42:57 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:49670/oidc2365--- PASS: TestValidateToken_NoMatchingProvider (0.12s)23662026/10/10 19:42:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49686/oidc2367--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.14s)23682026/10/10 19:42:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49688/oidc2369--- PASS: TestValidateToken_ValidToken (0.12s)23702026/10/10 19:42:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49691/oidc2371--- PASS: TestValidateToken_BoundClaimsMismatch (0.15s)23722026/10/10 19:42:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49693/oidc2373--- PASS: TestValidateToken_Expired (0.14s)23742026/10/10 19:42:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49695/oidc2375--- PASS: TestScopes_Rules (0.16s)23762026/10/10 19:42:57 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:49690/oidc23772026/10/10 19:42:57 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:49697/oidc2378--- PASS: TestValidateToken_MultipleProviders (0.17s)2379PASS2380Running hook tests...2381=== RUN TestSendPathsEmpty2382=== PAUSE TestSendPathsEmpty2383=== RUN TestQueueEnqueueAndFetch2384=== PAUSE TestQueueEnqueueAndFetch2385=== RUN TestQueueDeduplication2386=== PAUSE TestQueueDeduplication2387=== RUN TestQueueRemove2388=== PAUSE TestQueueRemove2389=== RUN TestQueueFetchBatchLimit2390=== PAUSE TestQueueFetchBatchLimit2391=== RUN TestQueueRetryMovesToBack2392=== PAUSE TestQueueRetryMovesToBack2393=== RUN TestQueueFetchRemoveLifecycle2394=== PAUSE TestQueueFetchRemoveLifecycle2395=== RUN TestQueueConcurrentWriters2396=== PAUSE TestQueueConcurrentWriters2397=== RUN TestQueueRemoveLargeClosure2398=== PAUSE TestQueueRemoveLargeClosure2399=== RUN TestServerClientIntegration2400--- PASS: TestServerClientIntegration (0.00s)2401=== RUN TestServerQueueError24022026/10/10 19:42:57 ERROR Failed to queue paths error="permission denied" count=12403--- PASS: TestServerQueueError (0.00s)2404=== RUN TestGetListenerSocketActivation2405 server_test.go:146: systemd socket activation does not exist on darwin2406--- SKIP: TestGetListenerSocketActivation (0.00s)2407=== RUN TestDrainIsolatesPoisonPath2408=== PAUSE TestDrainIsolatesPoisonPath2409=== RUN TestRunNotBlockedByPoisonHead2410=== PAUSE TestRunNotBlockedByPoisonHead2411=== RUN TestDrainGivesUpWhenServerDown2412=== PAUSE TestDrainGivesUpWhenServerDown2413=== RUN TestFailedPathPrunedByLaterClosure2414=== PAUSE TestFailedPathPrunedByLaterClosure2415=== RUN TestWorkerUploadsAndRemoves2416=== PAUSE TestWorkerUploadsAndRemoves2417=== RUN TestWorkerSkipsGCdPaths2418=== PAUSE TestWorkerSkipsGCdPaths2419=== RUN TestWorkerPrunesClosureDeps2420=== PAUSE TestWorkerPrunesClosureDeps2421=== RUN TestDrainTimeout2422=== PAUSE TestDrainTimeout2423=== CONT TestSendPathsEmpty2424=== CONT TestDrainIsolatesPoisonPath2425=== CONT TestWorkerSkipsGCdPaths2426--- PASS: TestSendPathsEmpty (0.00s)2427=== CONT TestQueueRemoveLargeClosure2428=== CONT TestQueueConcurrentWriters2429=== CONT TestQueueFetchRemoveLifecycle2430=== CONT TestQueueRetryMovesToBack2431=== CONT TestQueueDeduplication2432=== CONT TestQueueEnqueueAndFetch2433=== CONT TestWorkerUploadsAndRemoves2434=== CONT TestDrainTimeout2435=== CONT TestQueueRemove2436=== CONT TestWorkerPrunesClosureDeps2437=== CONT TestQueueFetchBatchLimit2438=== CONT TestDrainGivesUpWhenServerDown2439=== CONT TestFailedPathPrunedByLaterClosure2440=== CONT TestRunNotBlockedByPoisonHead24412026/10/10 19:42:57 INFO Upload queue status pending=22442--- PASS: TestQueueEnqueueAndFetch (0.01s)24432026/10/10 19:42:57 INFO Uploading batch count=224442026/10/10 19:42:57 INFO Upload queue status pending=224452026/10/10 19:42:57 INFO Uploading batch count=12446--- PASS: TestQueueFetchRemoveLifecycle (0.01s)24472026/10/10 19:42:57 INFO Upload queue status pending=324482026/10/10 19:42:57 INFO Uploading batch count=124492026/10/10 19:42:57 ERROR Upload failed error="upload failed" count=124502026/10/10 19:42:57 INFO Uploading batch count=22451--- PASS: TestQueueFetchBatchLimit (0.01s)24522026/10/10 19:42:57 INFO Uploading batch count=124532026/10/10 19:42:57 ERROR Upload failed error="upload failed" count=12454--- PASS: TestQueueRemove (0.01s)2455--- PASS: TestQueueDeduplication (0.02s)24562026/10/10 19:42:57 INFO Uploading batch count=224572026/10/10 19:42:57 ERROR Upload failed error="upload failed" count=224582026/10/10 19:42:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/fa1433502527f7cf/build/TestDrainGivesUpWhenServerDown3569324695/002/a24592026/10/10 19:42:57 INFO Uploading batch count=424602026/10/10 19:42:57 ERROR Upload failed error="upload failed" count=424612026/10/10 19:42:57 INFO Uploading batch count=124622026/10/10 19:42:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/fa1433502527f7cf/build/TestDrainGivesUpWhenServerDown3569324695/002/b24632026/10/10 19:42:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/fa1433502527f7cf/build/TestDrainIsolatesPoisonPath2853465610/002/bbb24642026/10/10 19:42:57 INFO Uploading batch count=124652026/10/10 19:42:57 INFO Upload queue status pending=22466--- PASS: TestQueueRetryMovesToBack (0.02s)24672026/10/10 19:42:57 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/7/scratch/fa1433502527f7cf/build/TestWorkerSkipsGCdPaths1335335238/002/nonexistent24682026/10/10 19:42:57 INFO Uploading batch count=224692026/10/10 19:42:57 ERROR Upload failed error="upload failed" count=224702026/10/10 19:42:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/fa1433502527f7cf/build/TestDrainGivesUpWhenServerDown3569324695/002/c24712026/10/10 19:42:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/fa1433502527f7cf/build/TestDrainGivesUpWhenServerDown3569324695/002/d24722026/10/10 19:42:57 INFO Uploading batch count=124732026/10/10 19:42:57 INFO Uploading batch count=124742026/10/10 19:42:57 ERROR Upload failed error="upload failed" count=124752026/10/10 19:42:57 INFO Uploading batch count=224762026/10/10 19:42:57 ERROR Upload failed error="upload failed" count=224772026/10/10 19:42:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/fa1433502527f7cf/build/TestDrainGivesUpWhenServerDown3569324695/002/e24782026/10/10 19:42:57 INFO Uploading batch count=124792026/10/10 19:42:57 ERROR Upload failed error="upload failed" count=124802026/10/10 19:42:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/fa1433502527f7cf/build/TestDrainGivesUpWhenServerDown3569324695/002/f24812026/10/10 19:42:57 INFO Uploading batch count=124822026/10/10 19:42:57 ERROR Upload failed error="upload failed" count=124832026/10/10 19:42:57 ERROR Drain finished with paths left in queue remaining=102484--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24852026/10/10 19:42:57 ERROR Drain finished with paths left in queue remaining=12486--- PASS: TestDrainIsolatesPoisonPath (0.02s)2487--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2488--- PASS: TestWorkerUploadsAndRemoves (0.03s)2489--- PASS: TestWorkerPrunesClosureDeps (0.03s)2490--- PASS: TestWorkerSkipsGCdPaths (0.04s)2491--- PASS: TestQueueRemoveLargeClosure (0.05s)2492--- PASS: TestQueueConcurrentWriters (0.16s)24932026/10/10 19:42:58 ERROR Upload failed error="context deadline exceeded" count=224942026/10/10 19:42:58 ERROR Drain finished with paths left in queue remaining=42495--- PASS: TestDrainTimeout (0.22s)24962026/10/10 19:42:58 INFO Uploading batch count=124972026/10/10 19:42:58 INFO Uploading batch count=124982026/10/10 19:42:58 INFO Uploading batch count=124992026/10/10 19:42:58 ERROR Upload failed error="upload failed" count=125002026/10/10 19:42:58 INFO Uploading batch count=125012026/10/10 19:42:58 ERROR Upload failed error="upload failed" count=125022026/10/10 19:42:58 INFO Uploading batch count=125032026/10/10 19:42:58 ERROR Upload failed error="upload failed" count=125042026/10/10 19:42:58 INFO Uploading batch count=125052026/10/10 19:42:58 ERROR Upload failed error="upload failed" count=125062026/10/10 19:42:58 ERROR Drain finished with paths left in queue remaining=12507--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2508PASS2509Running signing tests...2510=== RUN TestExternalSigner2511=== PAUSE TestExternalSigner2512=== RUN TestExternalSignerWrongPublicKey2513=== PAUSE TestExternalSignerWrongPublicKey2514=== RUN TestExternalSignerErrors2515=== PAUSE TestExternalSignerErrors2516=== RUN TestExternalSignerRestartsAfterCrash2517=== PAUSE TestExternalSignerRestartsAfterCrash2518=== RUN TestExternalSignerProgramErrorKeepsProcess2519=== PAUSE TestExternalSignerProgramErrorKeepsProcess2520=== RUN TestExternalSignerClose2521=== PAUSE TestExternalSignerClose2522=== RUN TestExternalSignerRejectsInvalidPublicKey2523=== PAUSE TestExternalSignerRejectsInvalidPublicKey2524=== RUN TestExternalSignerCancellation2525=== PAUSE TestExternalSignerCancellation2526=== RUN TestGenerateFingerprint2527=== PAUSE TestGenerateFingerprint2528=== RUN TestParseSigningKey2529=== PAUSE TestParseSigningKey2530=== RUN TestSign2531=== PAUSE TestSign2532=== RUN TestSignBatch2533=== PAUSE TestSignBatch2534=== RUN TestNilKeyPublicKey2535=== PAUSE TestNilKeyPublicKey2536=== RUN TestSignErrors2537=== PAUSE TestSignErrors2538=== CONT TestExternalSigner2539=== CONT TestExternalSignerCancellation2540=== CONT TestSignBatch2541=== CONT TestExternalSignerProgramErrorKeepsProcess2542=== CONT TestExternalSignerRejectsInvalidPublicKey2543=== RUN TestExternalSignerRejectsInvalidPublicKey/#002544=== CONT TestParseSigningKey2545=== RUN TestParseSigningKey/valid_32-byte_key2546=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002547=== CONT TestSign2548=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2549=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2550=== CONT TestExternalSignerClose2551=== CONT TestGenerateFingerprint2552=== RUN TestGenerateFingerprint/basic_with_references2553=== PAUSE TestGenerateFingerprint/basic_with_references2554=== RUN TestGenerateFingerprint/no_references2555=== PAUSE TestGenerateFingerprint/no_references2556=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2557=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2558=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2559=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2560=== RUN TestGenerateFingerprint/invalid_nar_hash_length2561=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2562=== RUN TestGenerateFingerprint/invalid_store_path_prefix2563=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2564=== RUN TestGenerateFingerprint/invalid_reference_prefix2565=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2566=== CONT TestGenerateFingerprint/basic_with_references2567=== CONT TestSignErrors2568=== CONT TestGenerateFingerprint/invalid_reference_prefix2569=== CONT TestExternalSignerErrors2570=== RUN TestExternalSignerErrors/wrong_signature_name2571=== PAUSE TestExternalSignerErrors/wrong_signature_name2572=== RUN TestExternalSignerErrors/invalid_signature_base642573=== PAUSE TestExternalSignerErrors/invalid_signature_base642574=== RUN TestExternalSignerErrors/exit_on_request2575=== PAUSE TestExternalSignerErrors/exit_on_request2576=== RUN TestExternalSignerErrors/invalid_JSON2577=== CONT TestExternalSignerRestartsAfterCrash2578=== CONT TestNilKeyPublicKey2579--- PASS: TestNilKeyPublicKey (0.00s)2580=== CONT TestExternalSignerWrongPublicKey2581=== PAUSE TestParseSigningKey/valid_32-byte_key2582=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2583=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2584=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2585=== CONT TestGenerateFingerprint/invalid_store_path_prefix2586=== CONT TestGenerateFingerprint/invalid_nar_hash_length2587=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2588=== CONT TestGenerateFingerprint/no_references2589--- PASS: TestGenerateFingerprint (0.00s)2590 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2591 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2592 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2593 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2594 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2595 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2596 --- PASS: TestGenerateFingerprint/no_references (0.00s)2597=== PAUSE TestExternalSignerErrors/invalid_JSON2598=== RUN TestExternalSignerErrors/wrong_shape2599=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2600=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2601=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2602=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2603=== PAUSE TestExternalSignerErrors/wrong_shape2604=== RUN TestParseSigningKey/no_colon2605=== PAUSE TestParseSigningKey/no_colon2606=== RUN TestParseSigningKey/empty_name2607=== PAUSE TestParseSigningKey/empty_name2608=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2609=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2610=== RUN TestExternalSignerErrors/wrong_signature_length2611=== PAUSE TestExternalSignerErrors/wrong_signature_length2612=== CONT TestExternalSignerRejectsInvalidPublicKey/#002613=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2614=== RUN TestParseSigningKey/invalid_base642615=== PAUSE TestParseSigningKey/invalid_base642616=== RUN TestExternalSignerErrors/wrong_id2617=== RUN TestParseSigningKey/wrong_length2618=== PAUSE TestParseSigningKey/wrong_length2619=== PAUSE TestExternalSignerErrors/wrong_id2620=== CONT TestParseSigningKey/valid_32-byte_key2621=== RUN TestExternalSignerErrors/null_signatures2622=== PAUSE TestExternalSignerErrors/null_signatures2623=== RUN TestExternalSignerErrors/unrequested_key2624=== PAUSE TestExternalSignerErrors/unrequested_key2625=== RUN TestExternalSignerErrors/missing_signature_name2626=== PAUSE TestExternalSignerErrors/missing_signature_name2627=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2628=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2629=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2630--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2631 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2632 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2633 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2634 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2635 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2636=== CONT TestParseSigningKey/wrong_length2637=== CONT TestParseSigningKey/invalid_base642638=== CONT TestParseSigningKey/empty_name2639=== CONT TestParseSigningKey/no_colon2640=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2641=== RUN TestExternalSignerErrors/program_error2642=== PAUSE TestExternalSignerErrors/program_error2643=== RUN TestExternalSignerErrors/null2644=== PAUSE TestExternalSignerErrors/null2645=== RUN TestExternalSignerErrors/missing_signatures2646=== PAUSE TestExternalSignerErrors/missing_signatures2647=== RUN TestExternalSignerErrors/exit_at_startup2648=== PAUSE TestExternalSignerErrors/exit_at_startup2649=== RUN TestExternalSignerErrors/wrong_signatures_shape2650=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2651=== RUN TestExternalSignerErrors/too_few_signatures2652=== PAUSE TestExternalSignerErrors/too_few_signatures2653=== CONT TestExternalSignerErrors/too_few_signatures2654=== CONT TestExternalSignerErrors/wrong_signature_name2655=== CONT TestExternalSignerErrors/unrequested_key2656=== CONT TestExternalSignerErrors/wrong_shape2657=== CONT TestExternalSignerErrors/exit_on_request2658=== CONT TestExternalSignerErrors/invalid_signature_base642659=== CONT TestExternalSignerErrors/wrong_signatures_shape2660=== CONT TestExternalSignerErrors/wrong_id2661=== CONT TestExternalSignerErrors/missing_signature_name2662=== CONT TestExternalSignerErrors/wrong_signature_length2663=== CONT TestExternalSignerErrors/missing_signatures2664=== CONT TestExternalSignerErrors/program_error2665=== CONT TestExternalSignerErrors/null2666=== RUN TestSignErrors/nil_key2667--- PASS: TestSign (0.00s)2668=== CONT TestExternalSignerErrors/exit_at_startup2669=== PAUSE TestSignErrors/nil_key2670=== RUN TestSignErrors/nil_narinfo2671=== PAUSE TestSignErrors/nil_narinfo2672=== RUN TestSignErrors/invalid_narinfo2673=== PAUSE TestSignErrors/invalid_narinfo2674=== RUN TestSignErrors/canceled2675=== PAUSE TestSignErrors/canceled2676=== CONT TestExternalSignerErrors/invalid_JSON2677--- PASS: TestSignBatch (0.00s)2678=== CONT TestSignErrors/nil_key2679=== CONT TestSignErrors/nil_narinfo2680=== CONT TestSignErrors/canceled2681=== CONT TestSignErrors/invalid_narinfo2682--- PASS: TestSignErrors (0.00s)2683 --- PASS: TestSignErrors/nil_key (0.00s)2684 --- PASS: TestSignErrors/nil_narinfo (0.00s)2685 --- PASS: TestSignErrors/canceled (0.00s)2686 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2687=== CONT TestExternalSignerErrors/null_signatures2688--- PASS: TestParseSigningKey (0.00s)2689 --- PASS: TestParseSigningKey/wrong_length (0.00s)2690 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2691 --- PASS: TestParseSigningKey/empty_name (0.00s)2692 --- PASS: TestParseSigningKey/no_colon (0.00s)2693 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2694 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2695--- PASS: TestExternalSigner (0.11s)2696--- PASS: TestExternalSignerClose (0.17s)2697--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.25s)2698--- PASS: TestExternalSignerWrongPublicKey (0.70s)2699--- PASS: TestExternalSignerRestartsAfterCrash (0.80s)2700/private/var/tb/7/scratch/fa1433502527f7cf/build/TestExternalSignerRestartsAfterCrash1836530091/001/sign program: line 7: /private/var/tb/7/scratch/fa1433502527f7cf/build/TestExternalSignerRestartsAfterCrash1836530091/001/sign program.starts: No such file or directory2701--- PASS: TestExternalSignerCancellation (1.10s)2702--- PASS: TestExternalSignerErrors (0.00s)2703 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.32s)2704 --- PASS: TestExternalSignerErrors/too_few_signatures (0.40s)2705 --- PASS: TestExternalSignerErrors/null (0.47s)2706 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.55s)2707 --- PASS: TestExternalSignerErrors/missing_signature_name (0.62s)2708 --- PASS: TestExternalSignerErrors/wrong_shape (0.85s)2709 --- PASS: TestExternalSignerErrors/missing_signatures (0.93s)2710 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.01s)2711 --- PASS: TestExternalSignerErrors/exit_on_request (1.16s)2712 --- PASS: TestExternalSignerErrors/wrong_id (1.24s)2713 --- PASS: TestExternalSignerErrors/unrequested_key (1.32s)2714 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.39s)2715 --- PASS: TestExternalSignerErrors/program_error (1.47s)2716 --- PASS: TestExternalSignerErrors/invalid_JSON (1.54s)2717 --- PASS: TestExternalSignerErrors/exit_at_startup (1.62s)2718 --- PASS: TestExternalSignerErrors/null_signatures (1.70s)2719PASS2720Running OpenBao signer tests...2721=== RUN TestSign2722=== PAUSE TestSign2723=== RUN TestSignErrors2724=== PAUSE TestSignErrors2725=== RUN TestServe2726=== PAUSE TestServe2727=== RUN TestServeRejectsGarbage2728=== PAUSE TestServeRejectsGarbage2729=== CONT TestSign2730=== CONT TestSignErrors2731=== RUN TestSignErrors/http_error2732=== PAUSE TestSignErrors/http_error2733=== RUN TestSignErrors/invalid_json2734=== PAUSE TestSignErrors/invalid_json2735=== RUN TestSignErrors/no_prefix2736=== PAUSE TestSignErrors/no_prefix2737=== RUN TestSignErrors/invalid_base642738=== CONT TestServeRejectsGarbage2739=== CONT TestServe2740=== PAUSE TestSignErrors/invalid_base642741=== CONT TestSignErrors/http_error2742=== CONT TestSignErrors/invalid_base642743=== CONT TestSignErrors/no_prefix2744=== CONT TestSignErrors/invalid_json2745--- PASS: TestServeRejectsGarbage (0.00s)2746--- PASS: TestServe (0.00s)2747--- PASS: TestSign (0.00s)2748--- PASS: TestSignErrors (0.00s)2749 --- PASS: TestSignErrors/no_prefix (0.00s)2750 --- PASS: TestSignErrors/invalid_base64 (0.00s)2751 --- PASS: TestSignErrors/http_error (0.00s)2752 --- PASS: TestSignErrors/invalid_json (0.00s)2753PASS