niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #415
· raw
1tribuchet: building on eliza2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestPartSizeForNAR20=== PAUSE TestPartSizeForNAR21=== RUN TestUploadMultipart_SupersededByPeer22=== PAUSE TestUploadMultipart_SupersededByPeer23=== RUN TestDumpPathCaseHackMatchesNix24--- PASS: TestDumpPathCaseHackMatchesNix (0.03s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== RUN TestSupersededNARStillUploadsListing28=== PAUSE TestSupersededNARStillUploadsListing29=== RUN TestDumpPathMatchesNix30=== PAUSE TestDumpPathMatchesNix31=== RUN TestDumpPathSingleFile32=== PAUSE TestDumpPathSingleFile33=== RUN TestDumpPathWriterError34=== PAUSE TestDumpPathWriterError35=== RUN TestEncodeNixBase3236=== PAUSE TestEncodeNixBase3237=== RUN TestEncodeNixBase32WithRealHash38=== PAUSE TestEncodeNixBase32WithRealHash39=== RUN TestConvertHashToNix3240=== PAUSE TestConvertHashToNix3241=== RUN TestGetStorePathHash42=== PAUSE TestGetStorePathHash43=== RUN TestPathInfoHashCompatibility44=== PAUSE TestPathInfoHashCompatibility45=== RUN TestParsePathInfoJSON46=== PAUSE TestParsePathInfoJSON47=== RUN TestParsePathInfoJSONMultiplePaths48=== PAUSE TestParsePathInfoJSONMultiplePaths49=== RUN TestPathInfoCACompatibility50=== PAUSE TestPathInfoCACompatibility51=== RUN TestRateLimiterFeedback52=== PAUSE TestRateLimiterFeedback53=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess54=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess55=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer56=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer57=== RUN TestResolveStorePath58=== PAUSE TestResolveStorePath59=== RUN TestDoWithRetry_BodyReplayedViaGetBody60=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody61=== RUN TestRetryTimeoutOutlastsMaxRetries62=== PAUSE TestRetryTimeoutOutlastsMaxRetries63=== RUN TestDoWithRetry_FinalResponseBodyReadable64=== PAUSE TestDoWithRetry_FinalResponseBodyReadable65=== RUN TestShellSplit66=== PAUSE TestShellSplit67=== RUN TestShellSplitErrors68=== PAUSE TestShellSplitErrors69=== RUN TestStreamPushReportsEveryPath70=== PAUSE TestStreamPushReportsEveryPath71=== RUN TestStreamPushBatchesUnderLoad72=== PAUSE TestStreamPushBatchesUnderLoad73=== RUN TestStreamPushIsolatesFailures74=== PAUSE TestStreamPushIsolatesFailures75=== RUN TestStreamPushGivesUpOnDeadServer76=== PAUSE TestStreamPushGivesUpOnDeadServer77=== RUN TestStreamPushRequestLine78=== PAUSE TestStreamPushRequestLine79=== RUN TestStreamPushReportsSignatures80=== PAUSE TestStreamPushReportsSignatures81=== RUN TestStreamPushReportsSkippedPaths82=== PAUSE TestStreamPushReportsSkippedPaths83=== RUN TestClientSignaturesByStorePath84=== PAUSE TestClientSignaturesByStorePath85=== RUN TestStreamPushStopsWhenCanceled86=== PAUSE TestStreamPushStopsWhenCanceled87=== RUN TestSetClientTLS88=== PAUSE TestSetClientTLS89=== RUN TestSetClientTLSDoesNotMutateDefaultTransport90=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport91=== RUN TestSetClientTLSErrors92=== PAUSE TestSetClientTLSErrors93=== RUN TestStaticToken94=== PAUSE TestStaticToken95=== RUN TestFileTokenReadsAndCaches96=== PAUSE TestFileTokenReadsAndCaches97=== RUN TestFileTokenMissing98=== PAUSE TestFileTokenMissing99=== RUN TestFileTokenEmpty100=== PAUSE TestFileTokenEmpty101=== RUN TestScriptTokenNoExpiryRerunsEveryCall102=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall103=== RUN TestScriptTokenCachesUntilRefresh104=== PAUSE TestScriptTokenCachesUntilRefresh105=== RUN TestScriptTokenEmptyToken106=== PAUSE TestScriptTokenEmptyToken107=== RUN TestScriptTokenBadJSON108=== PAUSE TestScriptTokenBadJSON109=== RUN TestScriptTokenScriptFails110=== PAUSE TestScriptTokenScriptFails111=== RUN TestScriptTokenEmptyCommand112=== PAUSE TestScriptTokenEmptyCommand113=== CONT TestDoServerRequestAttachesToken114=== CONT TestScriptTokenEmptyToken115=== CONT TestScriptTokenEmptyCommand116--- PASS: TestScriptTokenEmptyCommand (0.00s)117=== CONT TestStreamPushStopsWhenCanceled118--- PASS: TestStreamPushStopsWhenCanceled (0.00s)119=== CONT TestRetryTimeoutOutlastsMaxRetries120=== CONT TestScriptTokenScriptFails121=== CONT TestResolveStorePath122=== CONT TestScriptTokenCachesUntilRefresh123=== CONT TestStreamPushReportsSkippedPaths124=== CONT TestStreamPushReportsSignatures125--- PASS: TestScriptTokenScriptFails (0.00s)126=== CONT TestDoWithRetry_BodyReplayedViaGetBody127=== CONT TestScriptTokenNoExpiryRerunsEveryCall128=== CONT TestStreamPushRequestLine129=== CONT TestFileTokenEmpty130=== CONT TestStreamPushGivesUpOnDeadServer131=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess132=== CONT TestFileTokenMissing133=== CONT TestStreamPushIsolatesFailures134=== CONT TestFileTokenReadsAndCaches135=== CONT TestStreamPushBatchesUnderLoad1362026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:334851372026/10/14 16:44:52 ERROR Upload failed error="bad path" count=3138=== CONT TestStaticToken1392026/10/14 16:44:52 ERROR Upload failed error=boom count=11402026/10/14 16:44:52 ERROR Upload failed error="connection refused" count=201412026/10/14 16:44:52 WARN Rate limiter enabled after throttle name=server-test rate=51422026/10/14 16:44:52 WARN Rate limiter enabled after throttle name=server-test rate=51432026/10/14 16:44:52 ERROR Server seems unavailable, giving up on batch untried=171442026/10/14 16:44:52 ERROR Upload failed error=boom count=1145=== CONT TestStreamPushReportsEveryPath146=== CONT TestSetClientTLSErrors1472026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:41865148=== CONT TestShellSplitErrors149=== CONT TestSetClientTLSDoesNotMutateDefaultTransport150=== CONT TestShellSplit151=== CONT TestSetClientTLS152=== CONT TestDoWithRetry_FinalResponseBodyReadable153--- PASS: TestStreamPushReportsSkippedPaths (0.00s)154--- PASS: TestResolveStorePath (0.00s)155--- PASS: TestScriptTokenEmptyToken (0.00s)156--- PASS: TestFileTokenEmpty (0.00s)157--- PASS: TestStreamPushIsolatesFailures (0.00s)1582026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:33485159=== CONT TestClientSignaturesByStorePath1602026/10/14 16:44:52 WARN Rate limiter enabled after throttle name=server-test rate=5161=== CONT TestPartSizeForNAR162=== CONT TestDumpPathWriterError163=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer1642026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:44901165--- PASS: TestFileTokenMissing (0.00s)166=== CONT TestDumpPathSingleFile167=== CONT TestUploadMultipart_PartsInParallel168--- PASS: TestFileTokenReadsAndCaches (0.00s)169--- PASS: TestStaticToken (0.00s)170--- PASS: TestStreamPushReportsSignatures (0.00s)171=== CONT TestPathInfoCACompatibility1722026/10/14 16:44:52 WARN Rate limiter backed off name=server-test rate=5173=== RUN TestPathInfoCACompatibility/null_ca_field1742026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:41865175--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)176=== CONT TestDumpPathMatchesNix177=== PAUSE TestPathInfoCACompatibility/null_ca_field178=== CONT TestParsePathInfoJSONMultiplePaths179=== CONT TestSupersededNARStillUploadsListing180=== CONT TestParsePathInfoJSON181=== CONT TestUploadMultipart_SupersededByPeer182=== CONT TestPathInfoHashCompatibility183=== CONT TestRateLimiterFeedback184=== RUN TestPartSizeForNAR/zero_stays_at_minimum185--- PASS: TestStreamPushReportsEveryPath (0.00s)186--- PASS: TestShellSplitErrors (0.00s)187=== RUN TestPathInfoCACompatibility/old_string_format_-_text188=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text189--- PASS: TestShellSplit (0.00s)1902026/10/14 16:44:52 WARN Rate limiter backed off name=server-test rate=5191=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive192=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive193--- PASS: TestDoServerRequestAttachesToken (0.01s)194=== RUN TestPathInfoCACompatibility/new_structured_format_-_text195--- PASS: TestClientSignaturesByStorePath (0.00s)196=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths197=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text198--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)199=== CONT TestGetStorePathHash200=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths201--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)202=== CONT TestEncodeNixBase32WithRealHash2032026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:33485204--- PASS: TestEncodeNixBase32WithRealHash (0.00s)205=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method206=== RUN TestUploadMultipart_SupersededByPeer/exists207=== RUN TestGetStorePathHash/valid_store_path208=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths209=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)210=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum211=== RUN TestPartSizeForNAR/small_stays_at_minimum212=== CONT TestEncodeNixBase32213=== RUN TestEncodeNixBase32/test_string_hash214=== PAUSE TestEncodeNixBase32/test_string_hash215=== RUN TestEncodeNixBase32/empty_input216=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method217=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths218=== PAUSE TestUploadMultipart_SupersededByPeer/exists219=== RUN TestSupersededNARStillUploadsListing/small_NAR220=== RUN TestRateLimiterFeedback/429_enables_limiter221=== RUN TestSetClientTLS/rejects_connection_without_client_cert222=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert223=== RUN TestParsePathInfoJSON/Nix_format224=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA225--- PASS: TestScriptTokenCachesUntilRefresh (0.04s)226=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)227=== PAUSE TestParsePathInfoJSON/Nix_format228--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.04s)229=== RUN TestParsePathInfoJSON/Lix_format230=== CONT TestCaseHackSuffix231=== PAUSE TestParsePathInfoJSON/Lix_format232=== RUN TestParsePathInfoJSON/empty_input233=== PAUSE TestParsePathInfoJSON/empty_input234=== RUN TestParsePathInfoJSON/whitespace_only235=== PAUSE TestParsePathInfoJSON/whitespace_only236=== PAUSE TestEncodeNixBase32/empty_input237=== CONT TestConvertHashToNix32238=== RUN TestConvertHashToNix32/SRI_format_to_Nix32239=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32240=== RUN TestConvertHashToNix32/already_Nix32_format241=== PAUSE TestConvertHashToNix32/already_Nix32_format242=== RUN TestConvertHashToNix32/invalid_format243=== CONT TestRegisterUploadedObjectReusesConnections244=== RUN TestUploadMultipart_SupersededByPeer/missing245=== PAUSE TestUploadMultipart_SupersededByPeer/missing246=== PAUSE TestSupersededNARStillUploadsListing/small_NAR247=== RUN TestSupersededNARStillUploadsListing/dump_cut_short248--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.03s)249=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short250=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry2512026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:334852522026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:33485253=== CONT TestFilterOversizedClosures254=== RUN TestFilterOversizedClosures/no_limit_keeps_everything255=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything256=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA257=== RUN TestSetClientTLS/preserves_debug_logging_transport258=== PAUSE TestSetClientTLS/preserves_debug_logging_transport259=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon260=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon261=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI262=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI263=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512264=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512265=== PAUSE TestGetStorePathHash/valid_store_path266=== RUN TestGetStorePathHash/basename_without_hyphen_should_error267=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error268=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error269=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error270=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error271=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error272=== CONT TestScriptTokenBadJSON2732026/10/14 16:44:52 WARN Rate limiter enabled after throttle name=s3-test rate=52742026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:41259275=== RUN TestSetClientTLSErrors/missing_cert_file276=== PAUSE TestSetClientTLSErrors/missing_cert_file277=== RUN TestSetClientTLSErrors/missing_key_file278=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method279=== PAUSE TestSetClientTLSErrors/missing_key_file280=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun281=== PAUSE TestConvertHashToNix32/invalid_format282=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica283--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.00s)2842026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:33485285=== CONT TestPathInfoCACompatibility/old_string_format_-_text286=== PAUSE TestRateLimiterFeedback/429_enables_limiter287=== RUN TestRateLimiterFeedback/503_enables_limiter288=== PAUSE TestRateLimiterFeedback/503_enables_limiter289=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter290=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter291=== PAUSE TestPartSizeForNAR/small_stays_at_minimum292=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails293=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped294=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive295=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths296=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails297=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter298=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter299=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped300=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum301=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum302=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts303=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts304=== RUN TestPartSizeForNAR/1_TiB305=== PAUSE TestPartSizeForNAR/1_TiB306=== RUN TestPartSizeForNAR/5_TiB_S3_max_object307=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object308=== RUN TestPartSizeForNAR/capped_at_5_GiB309=== PAUSE TestPartSizeForNAR/capped_at_5_GiB310=== CONT TestUploadMultipart_SupersededByPeer/exists3112026/10/14 16:44:52 INFO Garbage collection started3122026/10/14 16:44:52 INFO Garbage collection started313=== CONT TestEncodeNixBase32/empty_input314=== CONT TestSetClientTLS/rejects_connection_without_client_cert315=== CONT TestUploadMultipart_SupersededByPeer/missing316=== RUN TestFilterOversizedClosures/all_closures_skipped317=== PAUSE TestFilterOversizedClosures/all_closures_skipped318=== RUN TestParsePathInfoJSON/invalid_JSON319=== PAUSE TestParsePathInfoJSON/invalid_JSON320=== CONT TestSetClientTLS/preserves_debug_logging_transport3212026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:33485322--- PASS: TestScriptTokenBadJSON (0.00s)323=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA324=== CONT TestPathInfoCACompatibility/new_structured_format_-_text325=== RUN TestSetClientTLSErrors/missing_ca_file326=== PAUSE TestSetClientTLSErrors/missing_ca_file327=== RUN TestSetClientTLSErrors/invalid_ca_file328=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths329=== CONT TestEncodeNixBase32/test_string_hash330=== CONT TestPathInfoCACompatibility/null_ca_field331=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)332=== PAUSE TestSetClientTLSErrors/invalid_ca_file333=== CONT TestGetStorePathHash/valid_store_path3342026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:33485335=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512336=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI337=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error338=== CONT TestConvertHashToNix32/SRI_format_to_Nix32339=== CONT TestConvertHashToNix32/invalid_format340=== CONT TestConvertHashToNix32/already_Nix32_format341=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error342=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3432026/10/14 16:44:52 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=0344=== CONT TestGetStorePathHash/basename_without_hyphen_should_error345--- PASS: TestParsePathInfoJSONMultiplePaths (0.03s)346 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)347 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)348--- PASS: TestPathInfoCACompatibility (0.03s)349 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)350 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)351 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)352 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)353 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.01s)354=== CONT TestPartSizeForNAR/zero_stays_at_minimum355=== CONT TestPartSizeForNAR/capped_at_5_GiB356=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter357=== CONT TestSupersededNARStillUploadsListing/small_NAR358=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter359=== CONT TestRateLimiterFeedback/429_enables_limiter360=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon3612026/10/14 16:44:52 INFO Uploading abc-hello (1.0GB)362=== CONT TestPartSizeForNAR/5_TiB_S3_max_object363=== CONT TestPartSizeForNAR/1_TiB364=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum365--- PASS: TestEncodeNixBase32 (0.00s)366 --- PASS: TestEncodeNixBase32/empty_input (0.00s)367 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)368=== CONT TestSupersededNARStillUploadsListing/dump_cut_short369=== CONT TestFilterOversizedClosures/no_limit_keeps_everything3702026/10/14 16:44:52 INFO Uploading abc-hello (1.0GB)371=== CONT TestParsePathInfoJSON/Nix_format372=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3732026/10/14 16:44:52 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=2000374=== CONT TestParsePathInfoJSON/empty_input375=== CONT TestRateLimiterFeedback/503_enables_limiter3762026/10/14 16:44:52 WARN Rate limiter enabled after throttle name=server-test rate=53772026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:33259378=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts379=== CONT TestParsePathInfoJSON/invalid_JSON380=== CONT TestParsePathInfoJSON/whitespace_only381=== CONT TestSetClientTLSErrors/missing_cert_file382=== CONT TestPartSizeForNAR/small_stays_at_minimum3832026/10/14 16:44:52 WARN Rate limiter backed off name=server-test rate=5384--- PASS: TestConvertHashToNix32 (0.00s)385 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)386 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)387 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)388--- PASS: TestGetStorePathHash (0.03s)389 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)390 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)391 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)392 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)393=== CONT TestSetClientTLSErrors/missing_key_file394=== CONT TestFilterOversizedClosures/all_closures_skipped3952026/10/14 16:44:52 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=50396--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)397=== CONT TestParsePathInfoJSON/Lix_format398=== CONT TestSetClientTLSErrors/missing_ca_file399--- PASS: TestUploadMultipart_SupersededByPeer (0.03s)400 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)401 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)402=== CONT TestSetClientTLSErrors/invalid_ca_file4032026/10/14 16:44:52 WARN Garbage collection finished on another replica. Its statistics are not available here4042026/10/14 16:44:52 WARN Rate limiter enabled after throttle name=server-test rate=54052026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:42779406--- PASS: TestPartSizeForNAR (0.04s)407 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)408 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)409 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)410 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)411 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)412 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)413 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)414--- PASS: TestPathInfoHashCompatibility (0.30s)415 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)416 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)417 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)418 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)419--- PASS: TestParsePathInfoJSON (0.01s)420 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)421 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)422 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)423 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)424 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)4252026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:33485426--- PASS: TestFilterOversizedClosures (0.27s)427 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)428 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)429 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)430--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.28s)4312026/10/14 16:44:52 WARN Rate limiter backed off name=server-test rate=5432--- PASS: TestRateLimiterFeedback (0.04s)433 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)434 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)435 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.27s)436 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.27s)437--- PASS: TestSetClientTLSErrors (0.05s)438 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)439 --- PASS: TestSetClientTLSErrors/missing_key_file (0.27s)440 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)441 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.27s)4422026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:334854432026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:33485444--- PASS: TestStreamPushBatchesUnderLoad (0.33s)445--- PASS: TestDumpPathSingleFile (0.32s)446--- PASS: TestCaseHackSuffix (0.29s)4472026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:334854482026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:334854492026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:334854502026/10/14 16:44:52 http: TLS handshake error from 127.0.0.1:43176: remote error: tls: bad certificate4512026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:33485452--- PASS: TestSetClientTLS (0.04s)453 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.28s)454 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.28s)455 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.29s)4562026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:334854572026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:33485458--- PASS: TestRegisterUploadedObjectReusesConnections (0.30s)459--- PASS: TestStreamPushRequestLine (0.34s)4602026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:334854612026/10/14 16:44:52 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:33485462--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.34s)463--- PASS: TestDumpPathWriterError (0.34s)4642026/10/14 16:44:52 INFO Uploading abc-hello (1.0GB)4652026/10/14 16:44:52 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:39711/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:39711/part/24662026/10/14 16:44:52 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"467--- PASS: TestDumpPathMatchesNix (0.38s)468--- PASS: TestSupersededNARStillUploadsListing (0.04s)469 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.28s)470 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.28s)471 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.83s)472--- PASS: TestUploadMultipart_PartsInParallel (0.89s)473--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4742026/10/14 16:44:53 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:46737/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:46737/api/uploads/complete4752026/10/14 16:44:53 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4762026/10/14 16:44:53 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:46737/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:46737/api/uploads/complete4772026/10/14 16:44:53 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4782026/10/14 16:44:53 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:46737/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:46737/api/uploads/complete4792026/10/14 16:44:53 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"480--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.03s)481PASS482Running server tests...483The files belonging to this database system will be owned by user "nixbld".484This user must also own the server process.485486The database cluster will be initialized with locale "C".487The default database encoding has accordingly been set to "SQL_ASCII".488The default text search configuration will be set to "english".489490Data page checksums are enabled.491492creating directory /build/postgres1389506406/data ... ok493creating subdirectories ... ok494selecting dynamic shared memory implementation ... posix495selecting default "max_connections" ... 100496selecting default "shared_buffers" ... 128MB497selecting default time zone ... UTC498creating configuration files ... ok499running bootstrap script ... ok500performing post-bootstrap initialization ... ok501syncing data to disk ... ok502503initdb: warning: enabling "trust" authentication for local connections504initdb: 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.505506Success. You can now start the database server using:507508 pg_ctl -D /build/postgres1389506406/data -l logfile start509510/build/postgres1389506406:5432 - no response5112026-10-14 16:44:54.366 UTC [129] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit5122026-10-14 16:44:54.367 UTC [129] LOG: listening on Unix socket "/build/postgres1389506406/.s.PGSQL.5432"5132026-10-14 16:44:54.370 UTC [136] LOG: database system was shut down at 2026-10-14 16:44:54 UTC5142026-10-14 16:44:54.374 UTC [129] LOG: database system is ready to accept connections515/build/postgres1389506406:5432 - accepting connections516=== RUN TestService_AuthMiddleware517=== PAUSE TestService_AuthMiddleware518=== RUN TestService_AuthMiddleware_MTLSProxyHeader519=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader520=== RUN TestService_AuthMiddleware_MTLSBoundSubjects521=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects522=== RUN TestService_ReadAuthMiddleware523=== PAUSE TestService_ReadAuthMiddleware524=== RUN TestService_AuthMiddleware_OIDC525=== PAUSE TestService_AuthMiddleware_OIDC526=== RUN TestService_RequireScope_OIDC527=== PAUSE TestService_RequireScope_OIDC528=== RUN TestService_ReadScope_PublicByDefault529=== PAUSE TestService_ReadScope_PublicByDefault530=== RUN TestCacheConfigHandler531=== PAUSE TestCacheConfigHandler532=== RUN TestCacheStatsHandler533=== PAUSE TestCacheStatsHandler534=== RUN TestClientCADerivations535=== PAUSE TestClientCADerivations536=== RUN TestClientErrorHandling537=== PAUSE TestClientErrorHandling538=== RUN TestClientIntegration539=== PAUSE TestClientIntegration540=== RUN TestClientMultipleUploads541=== PAUSE TestClientMultipleUploads542=== RUN TestClientWithDependencies543=== PAUSE TestClientWithDependencies544=== RUN TestClientSharedPathCommittedMidPush545=== PAUSE TestClientSharedPathCommittedMidPush546=== RUN TestPinProtectsFromGC547=== PAUSE TestPinProtectsFromGC548=== RUN TestClientPushesUseOnePush549=== PAUSE TestClientPushesUseOnePush550=== RUN TestClientFallsBackToClosures551=== PAUSE TestClientFallsBackToClosures552=== RUN TestDeleteClosuresRacingPins553=== PAUSE TestDeleteClosuresRacingPins554=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock555=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock556=== RUN TestResolveDBConnectionString557=== PAUSE TestResolveDBConnectionString558=== RUN TestConnectWaitsForAPeerMigration559=== PAUSE TestConnectWaitsForAPeerMigration560=== RUN TestLeadElectsOneAndHandsOver561=== PAUSE TestLeadElectsOneAndHandsOver562=== RUN TestLeadIncumbentWinsAfterRestart5632026/10/14 16:44:54 INFO lead: acquired remote=192.0.2.1:12345642026/10/14 16:44:55 INFO lead: released remote=192.0.2.1:12345652026/10/14 16:44:55 INFO lead: acquired remote=192.0.2.1:12345662026/10/14 16:44:56 INFO lead: released remote=192.0.2.1:1234567--- PASS: TestLeadIncumbentWinsAfterRestart (1.83s)568=== RUN TestLeadIncumbentAnnouncesAtOnce569=== PAUSE TestLeadIncumbentAnnouncesAtOnce570=== RUN TestLeadEndsOnShutdown571=== PAUSE TestLeadEndsOnShutdown572=== RUN TestLeadEndsWhenItsConnectionHangs5732026/10/14 16:44:56 INFO lead: acquired remote=192.0.2.1:12345742026-10-14 16:44:58.013 UTC [383] FATAL: terminating connection due to administrator command5752026/10/14 16:44:58 INFO lead: acquired remote=192.0.2.1:12345762026/10/14 16:44:59 WARN lead: lock connection lost error="timeout: context deadline exceeded"5772026/10/14 16:44:59 INFO lead: released remote=192.0.2.1:12345782026/10/14 16:44:59 INFO lead: released remote=192.0.2.1:1234579--- PASS: TestLeadEndsWhenItsConnectionHangs (3.11s)580=== RUN TestGCAdvisoryLockBlocksConcurrentRun581=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun582=== RUN TestGCBugBareHashReferences583=== PAUSE TestGCBugBareHashReferences584=== RUN TestGCMetrics585=== PAUSE TestGCMetrics586=== RUN TestPushDedupSurvivesConcurrentGC587=== PAUSE TestPushDedupSurvivesConcurrentGC588=== RUN TestDeduplicatedObjectsRecordedAsPending589=== PAUSE TestDeduplicatedObjectsRecordedAsPending590=== RUN TestGCSweepSkipsPendingObjects591=== PAUSE TestGCSweepSkipsPendingObjects592=== RUN TestTombstonedObjectOfferedWithoutWaiting593=== PAUSE TestTombstonedObjectOfferedWithoutWaiting594=== RUN TestGCSweepDeliversEachKeyOnce595=== PAUSE TestGCSweepDeliversEachKeyOnce596=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection597=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection598=== RUN TestForceGCDuringPushOffersSweptObject599=== PAUSE TestForceGCDuringPushOffersSweptObject600=== RUN TestFailedS3DeleteKeepsTombstone601=== PAUSE TestFailedS3DeleteKeepsTombstone602=== RUN TestSweepSkipsRowsLockedByPush603=== PAUSE TestSweepSkipsRowsLockedByPush604=== RUN TestRegisterCompletedObjectNeedsPendingRow605=== PAUSE TestRegisterCompletedObjectNeedsPendingRow606=== RUN TestGetExistingObjectsLocksRows607=== PAUSE TestGetExistingObjectsLocksRows608=== RUN TestSweepRechecksPendingAfterLocking609=== PAUSE TestSweepRechecksPendingAfterLocking610=== RUN TestPushWaitsForSweepHoldingRow611=== PAUSE TestPushWaitsForSweepHoldingRow612=== RUN TestCommitRacingPendingCleanupKeepsObjects613=== PAUSE TestCommitRacingPendingCleanupKeepsObjects614=== RUN TestGCEndsOnShutdown615=== PAUSE TestGCEndsOnShutdown616=== RUN TestGCTaskStore_StartNew617=== PAUSE TestGCTaskStore_StartNew618=== RUN TestGCTaskStore_DeduplicateSameParams619=== PAUSE TestGCTaskStore_DeduplicateSameParams620=== RUN TestGCTaskStore_ConflictDifferentParams621=== PAUSE TestGCTaskStore_ConflictDifferentParams622=== RUN TestGCTaskStore_GetEmpty623=== PAUSE TestGCTaskStore_GetEmpty624=== RUN TestGCTaskStore_GetReturnsLatest625=== PAUSE TestGCTaskStore_GetReturnsLatest626=== RUN TestGCTaskStore_CompletedAllowsNewTask627=== PAUSE TestGCTaskStore_CompletedAllowsNewTask628=== RUN TestGCTaskStore_PhaseUpdates629=== PAUSE TestGCTaskStore_PhaseUpdates630=== RUN TestGCTaskStore_Fail631=== PAUSE TestGCTaskStore_Fail632=== RUN TestGracefulShutdownDrainsInflight633=== PAUSE TestGracefulShutdownDrainsInflight634=== RUN TestService_healthCheckHandler635=== PAUSE TestService_healthCheckHandler636=== RUN TestService_readinessHandler637=== PAUSE TestService_readinessHandler638=== RUN TestGenerateLandingPage639=== PAUSE TestGenerateLandingPage640=== RUN TestCacheConfigHandlerMaxNarSize641=== PAUSE TestCacheConfigHandlerMaxNarSize642=== RUN TestCreatePendingClosureRejectsOversizedNAR643=== PAUSE TestCreatePendingClosureRejectsOversizedNAR644=== RUN TestNARDeduplicationMetadataUploadBug645=== PAUSE TestNARDeduplicationMetadataUploadBug646=== RUN TestMetricsInventory647=== PAUSE TestMetricsInventory648=== RUN TestMetricsCommit649=== PAUSE TestMetricsCommit650=== RUN TestService_NativeMTLS651=== PAUSE TestService_NativeMTLS652=== RUN TestServerTLSConfig653=== PAUSE TestServerTLSConfig654=== RUN TestMultipartCleanup655=== PAUSE TestMultipartCleanup656=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded657=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded658=== RUN TestPendingCleanupUsesOneCutoff659=== PAUSE TestPendingCleanupUsesOneCutoff660=== RUN TestObjectStatsTrigger661=== PAUSE TestObjectStatsTrigger662=== RUN TestObjectStatsLargeCommit663=== PAUSE TestObjectStatsLargeCommit664=== RUN TestOrphanedObjectsGC665=== PAUSE TestOrphanedObjectsGC666=== RUN TestOrphanedObjectsGCStressTest667=== PAUSE TestOrphanedObjectsGCStressTest668=== RUN TestCreatePin_ReservedPins669=== PAUSE TestCreatePin_ReservedPins670=== RUN TestPresentReportsOnlyClosureRoots671=== PAUSE TestPresentReportsOnlyClosureRoots672=== RUN TestPresentRefreshesOnlyStaleClosures673=== PAUSE TestPresentRefreshesOnlyStaleClosures674=== RUN TestPresentNotReportedWhileGCDeletesClosure675=== PAUSE TestPresentNotReportedWhileGCDeletesClosure676=== RUN TestParseSingleRange677=== PAUSE TestParseSingleRange678=== RUN TestProxyHeadersOnlyTrustedOnSocket6792026/10/14 16:44:59 INFO Starting HTTP server address=127.0.0.1:356116802026/10/14 16:44:59 INFO Starting HTTP server address=proxy.sock6812026/10/14 16:44:59 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6822026/10/14 16:44:59 INFO Shutdown signal received, draining in-flight requests timeout=10s683--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.10s)684=== RUN TestIsValidCachePath685=== PAUSE TestIsValidCachePath686=== RUN TestReadProxyNarinfo687=== PAUSE TestReadProxyNarinfo688=== RUN TestReadProxyNarinfoAlreadyDecompressed689=== PAUSE TestReadProxyNarinfoAlreadyDecompressed690=== RUN TestReadProxyContentNegotiation691=== PAUSE TestReadProxyContentNegotiation692=== RUN TestReadProxyNarStreaming693=== PAUSE TestReadProxyNarStreaming694=== RUN TestReadProxy404695=== PAUSE TestReadProxy404696=== RUN TestReadProxyInvalidPath697=== PAUSE TestReadProxyInvalidPath698=== RUN TestReadProxyHead699=== PAUSE TestReadProxyHead700=== RUN TestReadProxyOutlastsServerWriteTimeout701=== PAUSE TestReadProxyOutlastsServerWriteTimeout702=== RUN TestReadProxyConditionalGet703=== PAUSE TestReadProxyConditionalGet704=== RUN TestReadProxyRootRedirectsToIndexHTML705=== PAUSE TestReadProxyRootRedirectsToIndexHTML706=== RUN TestReadProxyDisabled707=== PAUSE TestReadProxyDisabled708=== RUN TestReadRedirectNar709=== PAUSE TestReadRedirectNar710=== RUN TestReadRedirectKeepsNarinfoProxied711=== PAUSE TestReadRedirectKeepsNarinfoProxied712=== RUN TestReadProxyRangeRequest713=== PAUSE TestReadProxyRangeRequest714=== RUN TestReadRedirectUsesPublicS3URL715=== PAUSE TestReadRedirectUsesPublicS3URL716=== RUN TestPush_OverlappingRootsStoreOneRowPerKey717=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey718=== RUN TestPush_CompleteCommitsEveryRoot719=== PAUSE TestPush_CompleteCommitsEveryRoot720=== RUN TestPush_RepeatedRootCommitsOnce721=== PAUSE TestPush_RepeatedRootCommitsOnce722=== RUN TestPush_CompleteWaitsForCleanupOfThePush723=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush724=== RUN TestPush_RootsAreLockedInByteOrder725=== PAUSE TestPush_RootsAreLockedInByteOrder726=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit727=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit728=== RUN TestPush_RejectsBadRequests729=== PAUSE TestPush_RejectsBadRequests730=== RUN TestPush_SignsNarinfosOfItsPendingObjects731=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects732=== RUN TestRedundantMultipartUpload733=== PAUSE TestRedundantMultipartUpload734=== RUN TestCompleteMultipartUpload_ErrorButObjectExists735=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists736=== RUN TestCompletedNarNotReofferedAcrossClosures737=== PAUSE TestCompletedNarNotReofferedAcrossClosures738=== RUN TestPresignedUploadRegisteredBeforeCommit739=== PAUSE TestPresignedUploadRegisteredBeforeCommit740=== RUN TestService_Rustfstest741=== PAUSE TestService_Rustfstest742=== RUN TestParseSize743=== PAUSE TestParseSize744=== RUN TestSkippedUploadsHandler745=== PAUSE TestSkippedUploadsHandler746=== RUN TestSystemdListenerNotActivated747--- PASS: TestSystemdListenerNotActivated (0.00s)748=== RUN TestWatchdogBeatsWhenHealthy749--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)750=== RUN TestWatchdogSkipsWhenUnhealthy7512026/10/14 16:44:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7522026/10/14 16:44:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7532026/10/14 16:44:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7542026/10/14 16:44:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7552026/10/14 16:44:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7562026/10/14 16:44:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7572026/10/14 16:44:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/14 16:44:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/14 16:44:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/14 16:44:59 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"761--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)762=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle763=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle764=== RUN TestProxyWriteTimeout765=== PAUSE TestProxyWriteTimeout766=== RUN TestPendingClosureWriteTimeout767=== PAUSE TestPendingClosureWriteTimeout768=== RUN TestIsValidUploadKey769=== PAUSE TestIsValidUploadKey770=== RUN TestUploadHandlersRejectInvalidKeys771=== PAUSE TestUploadHandlersRejectInvalidKeys772=== RUN TestUploadHandlersRejectOversizedBody773=== PAUSE TestUploadHandlersRejectOversizedBody774=== RUN TestService_cleanupPendingClosuresHandler775=== PAUSE TestService_cleanupPendingClosuresHandler776=== RUN TestService_createPendingClosureHandler777=== PAUSE TestService_createPendingClosureHandler778=== RUN TestService_verifyS3Integrity779=== PAUSE TestService_verifyS3Integrity780=== RUN TestCompleteMultipartUnregistered781=== PAUSE TestCompleteMultipartUnregistered782=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT783=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT784=== CONT TestProxyWriteTimeout785=== RUN TestProxyWriteTimeout/narinfo786=== CONT TestService_AuthMiddleware787=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle788=== CONT TestSkippedUploadsHandler789=== CONT TestParseSize790--- PASS: TestParseSize (0.00s)791=== CONT TestGCTaskStore_DeduplicateSameParams792--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)793=== CONT TestService_Rustfstest794=== CONT TestPresignedUploadRegisteredBeforeCommit795=== CONT TestCompletedNarNotReofferedAcrossClosures796=== CONT TestCompleteMultipartUpload_ErrorButObjectExists7972026/10/14 16:44:59 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000798=== CONT TestService_cleanupPendingClosuresHandler799=== CONT TestRedundantMultipartUpload800=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT801=== CONT TestPush_SignsNarinfosOfItsPendingObjects802=== CONT TestCompleteMultipartUnregistered803=== CONT TestPush_RejectsBadRequests804=== CONT TestService_verifyS3Integrity805=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit806=== CONT TestService_createPendingClosureHandler807=== CONT TestPush_RootsAreLockedInByteOrder808=== CONT TestPush_CompleteWaitsForCleanupOfThePush809=== CONT TestGCTaskStore_GetReturnsLatest810--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)811=== CONT TestGCTaskStore_GetEmpty812--- PASS: TestGCTaskStore_GetEmpty (0.00s)813=== CONT TestOrphanedObjectsGCStressTest814=== CONT TestGCTaskStore_ConflictDifferentParams815--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)816=== CONT TestGCEndsOnShutdown817=== RUN TestGCEndsOnShutdown/before_the_run818=== PAUSE TestGCEndsOnShutdown/before_the_run819=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete820=== CONT TestPush_RepeatedRootCommitsOnce821--- PASS: TestSkippedUploadsHandler (0.01s)822=== CONT TestOrphanedObjectsGC823=== PAUSE TestProxyWriteTimeout/narinfo824=== RUN TestProxyWriteTimeout/1_GiB_nar825=== CONT TestPush_CompleteCommitsEveryRoot826=== CONT TestGCTaskStore_StartNew827--- PASS: TestGCTaskStore_StartNew (0.00s)828=== CONT TestCommitRacingPendingCleanupKeepsObjects829=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete830=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark831=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark832=== PAUSE TestProxyWriteTimeout/1_GiB_nar833=== CONT TestObjectStatsLargeCommit834=== RUN TestProxyWriteTimeout/10_GiB_nar835=== PAUSE TestProxyWriteTimeout/10_GiB_nar836=== RUN TestProxyWriteTimeout/unknown_size837=== PAUSE TestProxyWriteTimeout/unknown_size838=== CONT TestPushWaitsForSweepHoldingRow8392026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures840--- PASS: TestService_Rustfstest (0.32s)841=== CONT TestObjectStatsTrigger8422026/10/14 16:45:00 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"843--- PASS: TestService_AuthMiddleware (0.34s)844=== CONT TestSweepRechecksPendingAfterLocking8452026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures8462026/10/14 16:45:00 INFO Received cleanup request method=DELETE path=/api/pending_closures8472026/10/14 16:45:00 INFO Aborted multipart uploads count=0 kept=08482026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures8492026/10/14 16:45:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8502026/10/14 16:45:00 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NzJkOTc2NTAtZDViNi00ODg4LWFhNWQtZGQxMzBmNDA4YWQ3LjY5YzkxYzQzLTcwMGQtNDgwMS05NjBhLWE2OGM0Njk4NGI1OHgxNzkxOTk2MzAwMzEyOTA2MzUw8512026/10/14 16:45:00 INFO Received cleanup request method=DELETE path=/api/pending_closures8522026/10/14 16:45:00 INFO Aborted multipart uploads count=1 kept=08532026/10/14 16:45:00 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NzJkOTc2NTAtZDViNi00ODg4LWFhNWQtZGQxMzBmNDA4YWQ3LjY5YzkxYzQzLTcwMGQtNDgwMS05NjBhLWE2OGM0Njk4NGI1OHgxNzkxOTk2MzAwMzEyOTA2MzUw parts=18542026/10/14 16:45:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8552026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures856--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.43s)857=== CONT TestPendingCleanupUsesOneCutoff8582026-10-14 16:45:00.371 UTC [460] ERROR: Closure does not exist: id=18592026-10-14 16:45:00.371 UTC [460] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE8602026-10-14 16:45:00.371 UTC [460] STATEMENT: -- name: CommitPendingClosure :one861 SELECT commit_pending_closure($1::bigint)::bigint862 863--- PASS: TestService_cleanupPendingClosuresHandler (0.43s)864=== CONT TestGetExistingObjectsLocksRows865=== RUN TestPush_RejectsBadRequests/bad_root866=== PAUSE TestPush_RejectsBadRequests/bad_root867=== RUN TestPush_RejectsBadRequests/root_not_in_objects868=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects869=== RUN TestPush_RejectsBadRequests/no_roots870=== PAUSE TestPush_RejectsBadRequests/no_roots871=== RUN TestPush_RejectsBadRequests/no_objects872=== PAUSE TestPush_RejectsBadRequests/no_objects873=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded8742026/10/14 16:45:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8752026/10/14 16:45:00 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst876--- PASS: TestCompleteMultipartUnregistered (0.47s)877=== CONT TestCreatePin_ReservedPins8782026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures8792026/10/14 16:45:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete880--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.51s)881=== CONT TestMultipartCleanup8822026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures8832026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures8842026/10/14 16:45:00 INFO Received push request method=POST path=/api/pushes8852026/10/14 16:45:00 INFO Received complete push request method=POST path=/api/pushes/1/complete8862026/10/14 16:45:00 INFO Received push request method=POST path=/api/pushes8872026/10/14 16:45:00 INFO Completed push id=1 objects=4 duration=8.224273ms8882026/10/14 16:45:00 INFO Received push request method=POST path=/api/pushes8892026/10/14 16:45:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8902026/10/14 16:45:00 INFO Signed narinfos id=1 count=18912026/10/14 16:45:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8922026/10/14 16:45:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8932026/10/14 16:45:00 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"8942026/10/14 16:45:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8952026/10/14 16:45:00 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"8962026/10/14 16:45:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8972026/10/14 16:45:00 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=18982026/10/14 16:45:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8992026/10/14 16:45:00 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo900--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.59s)901=== CONT TestRegisterCompletedObjectNeedsPendingRow9022026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures9032026/10/14 16:45:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43383/oidc9042026/10/14 16:45:00 INFO Received push request method=POST path=/api/pushes9052026/10/14 16:45:00 INFO Aborted multipart uploads count=0 kept=09062026/10/14 16:45:00 WARN Force mode enabled - objects will be deleted immediately without grace period9072026/10/14 16:45:00 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=09082026/10/14 16:45:00 INFO Vacuumed table table=pending_closures9092026/10/14 16:45:00 INFO Vacuumed table table=pending_objects9102026/10/14 16:45:00 INFO Vacuumed table table=multipart_uploads9112026/10/14 16:45:00 INFO Vacuumed table table=closures9122026/10/14 16:45:00 INFO Vacuumed table table=objects9132026/10/14 16:45:00 INFO Received complete push request method=POST path=/api/pushes/2/complete9142026/10/14 16:45:00 INFO Completed push id=2 objects=4 duration=3.499011ms915--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.68s)916=== CONT TestServerTLSConfig917=== RUN TestServerTLSConfig/no_client_CA918=== PAUSE TestServerTLSConfig/no_client_CA919=== RUN TestServerTLSConfig/missing_CA_file920=== PAUSE TestServerTLSConfig/missing_CA_file921=== RUN TestServerTLSConfig/not_a_PEM_file922=== PAUSE TestServerTLSConfig/not_a_PEM_file923=== CONT TestPush_OverlappingRootsStoreOneRowPerKey9242026/10/14 16:45:00 INFO Aborted multipart uploads count=0 kept=09252026/10/14 16:45:00 WARN Force mode enabled - objects will be deleted immediately without grace period9262026/10/14 16:45:00 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=09272026/10/14 16:45:00 INFO Vacuumed table table=pending_closures9282026/10/14 16:45:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9292026/10/14 16:45:00 INFO Vacuumed table table=pending_objects9302026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures9312026/10/14 16:45:00 INFO Vacuumed table table=multipart_uploads9322026/10/14 16:45:00 INFO Vacuumed table table=closures9332026/10/14 16:45:00 INFO Vacuumed table table=objects934--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.71s)935=== CONT TestSweepSkipsRowsLockedByPush9362026/10/14 16:45:00 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NzJkOTc2NTAtZDViNi00ODg4LWFhNWQtZGQxMzBmNDA4YWQ3LmRlMmIxNWYzLWFjZjgtNDBkNC1iMmYwLTE0YmZmOTMzZTAxOXgxNzkxOTk2MzAwMjU4NDU4NTY1 parts=129372026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures9382026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures9392026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures9402026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures941--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.72s)942=== CONT TestService_NativeMTLS9432026/10/14 16:45:00 INFO Received push request method=POST path=/api/pushes9442026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures9452026/10/14 16:45:00 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9462026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures9472026-10-14 16:45:00.728 UTC [543] ERROR: could not obtain lock on row in relation "closures"9482026-10-14 16:45:00.728 UTC [543] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9492026-10-14 16:45:00.728 UTC [543] ERROR: could not obtain lock on row in relation "closures"9502026-10-14 16:45:00.728 UTC [543] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9512026-10-14 16:45:00.728 UTC [543] ERROR: could not obtain lock on row in relation "closures"9522026-10-14 16:45:00.728 UTC [543] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9532026-10-14 16:45:00.729 UTC [543] ERROR: could not obtain lock on row in relation "closures"9542026-10-14 16:45:00.729 UTC [543] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9552026-10-14 16:45:00.729 UTC [543] ERROR: could not obtain lock on row in relation "closures"9562026-10-14 16:45:00.729 UTC [543] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT957--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.79s)958=== CONT TestReadRedirectUsesPublicS3URL9592026/10/14 16:45:00 INFO Received push request method=POST path=/api/pushes960--- PASS: TestPush_RootsAreLockedInByteOrder (0.79s)961=== CONT TestFailedS3DeleteKeepsTombstone9622026/10/14 16:45:00 INFO Received complete push request method=POST path=/api/pushes/1/complete9632026/10/14 16:45:00 INFO Received push request method=POST path=/api/pushes9642026/10/14 16:45:00 INFO Completed push id=1 objects=6 duration=11.397501ms965--- PASS: TestPush_CompleteCommitsEveryRoot (0.82s)966=== CONT TestMetricsCommit9672026/10/14 16:45:00 INFO Received complete push request method=POST path=/api/pushes/1/complete9682026/10/14 16:45:00 INFO Completed push id=1 objects=4 duration=10.729555ms969--- PASS: TestPush_RepeatedRootCommitsOnce (0.84s)970=== CONT TestReadProxyRangeRequest971--- PASS: TestObjectStatsTrigger (0.53s)972=== CONT TestForceGCDuringPushOffersSweptObject973=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows974=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows975=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check976=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check977=== CONT TestMetricsInventory9782026/10/14 16:45:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9792026/10/14 16:45:00 INFO Aborted multipart uploads count=0 kept=09802026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures9812026/10/14 16:45:00 WARN Force mode enabled - objects will be deleted immediately without grace period9822026/10/14 16:45:00 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NzJkOTc2NTAtZDViNi00ODg4LWFhNWQtZGQxMzBmNDA4YWQ3LjQ2NTk5ZjkzLTA3MTUtNDY3NS05MTNmLWFhNGU0ZjkxOWJiMXgxNzkxOTk2MzAwNDY2NzcwMjIx parts=129832026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures9842026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures9852026/10/14 16:45:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9862026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures9872026/10/14 16:45:00 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=09882026/10/14 16:45:00 INFO Vacuumed table table=pending_closures9892026/10/14 16:45:00 INFO Received cleanup request method=DELETE path=/api/pending_closures9902026/10/14 16:45:00 INFO Vacuumed table table=pending_objects9912026/10/14 16:45:00 INFO Vacuumed table table=multipart_uploads9922026/10/14 16:45:00 INFO Vacuumed table table=closures9932026/10/14 16:45:00 INFO Vacuumed table table=objects994--- PASS: TestSweepRechecksPendingAfterLocking (0.57s)995=== CONT TestReadRedirectKeepsNarinfoProxied9962026/10/14 16:45:00 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NzJkOTc2NTAtZDViNi00ODg4LWFhNWQtZGQxMzBmNDA4YWQ3LjgzYTkzZDlkLTcxZTItNGIxZC1iOGJmLTg1ODk4ZjMyMzMxZngxNzkxOTk2MzAwNTQ3NjM3Mjgx parts=109972026/10/14 16:45:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9982026/10/14 16:45:00 INFO Completed upload id=1 objects=2 duration=3.441151ms9992026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures1000--- PASS: TestGetExistingObjectsLocksRows (0.49s)1001=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection10022026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures10032026/10/14 16:45:00 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10042026/10/14 16:45:00 WARN Found objects in DB but missing from S3, will re-upload count=11005--- PASS: TestService_verifyS3Integrity (0.92s)1006=== CONT TestNARDeduplicationMetadataUploadBug10072026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures10082026-10-14 16:45:00.881 UTC [506] ERROR: Push does not exist: id=110092026-10-14 16:45:00.881 UTC [506] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE10102026-10-14 16:45:00.881 UTC [506] STATEMENT: SELECT commit_push($1)1011--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.93s)1012=== CONT TestReadRedirectNar1013--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.50s)1014=== CONT TestGCSweepDeliversEachKeyOnce10152026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures1016=== NAME TestOrphanedObjectsGC1017 orphaned_objects_gc_test.go:287: GC Test Summary:1018 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1019 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1020 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1021 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1022 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1023--- PASS: TestOrphanedObjectsGC (0.97s)1024=== CONT TestCreatePendingClosureRejectsOversizedNAR10252026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures1026--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1027=== CONT TestReadProxyDisabled1028--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.39s)1029=== CONT TestTombstonedObjectOfferedWithoutWaiting10302026/10/14 16:45:00 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10312026/10/14 16:45:00 WARN Refused reserved pin name=worker-x86_64-linux10322026/10/14 16:45:00 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10332026/10/14 16:45:00 INFO Received create pin request method=POST path=/api/pins/my-app10342026/10/14 16:45:00 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1035--- PASS: TestCreatePin_ReservedPins (0.53s)1036=== CONT TestCacheConfigHandlerMaxNarSize1037--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1038=== CONT TestReadProxyRootRedirectsToIndexHTML10392026/10/14 16:45:00 INFO Received push request method=POST path=/api/pushes10402026/10/14 16:45:00 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10412026/10/14 16:45:00 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NzJkOTc2NTAtZDViNi00ODg4LWFhNWQtZGQxMzBmNDA4YWQ3LjI4ZTM3ZmI5LWYwY2ItNGY0Mi1iZmQ3LTVhOGUwMjE1MWYzZHgxNzkxOTk2MzAwNjczODY1MTY1 parts=1010422026/10/14 16:45:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1043--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.36s)1044=== CONT TestGCSweepSkipsPendingObjects10452026/10/14 16:45:00 INFO Completed upload id=1 objects=2 duration=3.692713ms10462026/10/14 16:45:00 WARN mTLS auth: subject not in bound subjects subject="CN=reader"10472026/10/14 16:45:00 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1048--- PASS: TestService_NativeMTLS (0.32s)1049=== CONT TestGenerateLandingPage10502026/10/14 16:45:00 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001051--- PASS: TestGenerateLandingPage (0.00s)10522026/10/14 16:45:00 INFO Received uploads request method=POST path=/api/pending_closures1053=== CONT TestReadProxyConditionalGet10542026/10/14 16:45:00 INFO Starting cleanup of old closures method=DELETE path=/api/closures10552026/10/14 16:45:01 INFO Aborted multipart uploads count=0 kept=010562026/10/14 16:45:01 INFO Received cleanup request method=DELETE path=/api/pending_closures10572026/10/14 16:45:01 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket33/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""10582026/10/14 16:45:01 INFO Aborted multipart uploads count=0 kept=110592026/10/14 16:45:01 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=010602026/10/14 16:45:01 INFO Received cleanup request method=DELETE path=/api/pending_closures10612026/10/14 16:45:01 INFO Aborted multipart uploads count=1 kept=010622026/10/14 16:45:01 INFO Vacuumed table table=pending_closures10632026/10/14 16:45:01 INFO Vacuumed table table=pending_objects1064--- PASS: TestMultipartCleanup (0.57s)1065=== CONT TestService_readinessHandler10662026/10/14 16:45:01 INFO Vacuumed table table=multipart_uploads10672026/10/14 16:45:01 INFO Aborted multipart uploads count=0 kept=010682026/10/14 16:45:01 INFO Vacuumed table table=closures10692026/10/14 16:45:01 INFO Vacuumed table table=objects10702026/10/14 16:45:01 WARN Force mode enabled - objects will be deleted immediately without grace period10712026/10/14 16:45:01 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001072--- PASS: TestService_createPendingClosureHandler (1.10s)1073=== CONT TestDeduplicatedObjectsRecordedAsPending10742026/10/14 16:45:01 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=010752026/10/14 16:45:01 INFO Vacuumed table table=pending_closures10762026/10/14 16:45:01 INFO Vacuumed table table=pending_objects10772026/10/14 16:45:01 INFO Vacuumed table table=multipart_uploads10782026/10/14 16:45:01 INFO Vacuumed table table=closures10792026/10/14 16:45:01 INFO Vacuumed table table=objects1080--- PASS: TestReadRedirectUsesPublicS3URL (0.32s)1081=== CONT TestService_healthCheckHandler10822026/10/14 16:45:01 INFO Aborted multipart uploads count=0 kept=010832026/10/14 16:45:01 WARN Force mode enabled - objects will be deleted immediately without grace period10842026/10/14 16:45:01 INFO Received uploads request method=POST path=/api/pending_closures10852026/10/14 16:45:01 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=010862026/10/14 16:45:01 INFO Vacuumed table table=pending_closures10872026/10/14 16:45:01 INFO Vacuumed table table=pending_objects10882026/10/14 16:45:01 INFO Vacuumed table table=multipart_uploads10892026/10/14 16:45:01 INFO Vacuumed table table=closures10902026/10/14 16:45:01 INFO Vacuumed table table=objects1091--- PASS: TestSweepSkipsRowsLockedByPush (0.42s)1092=== CONT TestGracefulShutdownDrainsInflight10932026/10/14 16:45:01 INFO Starting HTTP server address=127.0.0.1:4343110942026/10/14 16:45:01 INFO Shutdown signal received, draining in-flight requests timeout=10s10952026/10/14 16:45:01 INFO Received push request method=POST path=/api/pushes10962026/10/14 16:45:01 INFO Received complete push request method=POST path=/api/pushes/1/complete10972026/10/14 16:45:01 INFO Completed push id=1 objects=4 duration=9.056421ms10982026/10/14 16:45:01 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10992026/10/14 16:45:01 INFO Completed upload id=2 objects=2 duration=1.471673ms1100--- PASS: TestReadProxyRangeRequest (0.34s)1101=== CONT TestPushDedupSurvivesConcurrentGC1102--- PASS: TestMetricsCommit (0.36s)1103=== CONT TestReadProxyOutlastsServerWriteTimeout1104--- PASS: TestPushWaitsForSweepHoldingRow (1.20s)1105=== CONT TestGCTaskStore_Fail1106--- PASS: TestGCTaskStore_Fail (0.00s)1107=== CONT TestGCMetrics1108--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1109=== CONT TestGCTaskStore_PhaseUpdates1110--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1111=== CONT TestReadProxyNarinfo11122026/10/14 16:45:01 INFO Aborted multipart uploads count=0 kept=01113--- PASS: TestMetricsInventory (0.36s)1114=== CONT TestGCBugBareHashReferences11152026/10/14 16:45:01 WARN Force mode enabled - objects will be deleted immediately without grace period11162026/10/14 16:45:01 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11172026/10/14 16:45:01 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1118--- PASS: TestReadRedirectKeepsNarinfoProxied (0.31s)1119=== CONT TestGCTaskStore_CompletedAllowsNewTask1120--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1121=== CONT TestIsValidCachePath1122=== RUN TestIsValidCachePath/narinfo1123=== PAUSE TestIsValidCachePath/narinfo1124=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1125=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1126=== RUN TestIsValidCachePath/nar_zst1127=== PAUSE TestIsValidCachePath/nar_zst1128=== RUN TestIsValidCachePath/nar_xz1129=== PAUSE TestIsValidCachePath/nar_xz1130=== RUN TestIsValidCachePath/nar_bz21131=== PAUSE TestIsValidCachePath/nar_bz21132=== RUN TestIsValidCachePath/nar_uncompressed1133=== PAUSE TestIsValidCachePath/nar_uncompressed1134=== RUN TestIsValidCachePath/ls1135=== PAUSE TestIsValidCachePath/ls1136=== RUN TestIsValidCachePath/log1137=== PAUSE TestIsValidCachePath/log1138=== RUN TestIsValidCachePath/realisation1139=== PAUSE TestIsValidCachePath/realisation1140=== RUN TestIsValidCachePath/nix-cache-info1141=== PAUSE TestIsValidCachePath/nix-cache-info1142=== RUN TestIsValidCachePath/index.html1143=== PAUSE TestIsValidCachePath/index.html1144=== RUN TestIsValidCachePath/traversal_parent1145=== PAUSE TestIsValidCachePath/traversal_parent1146=== RUN TestIsValidCachePath/traversal_in_middle1147=== PAUSE TestIsValidCachePath/traversal_in_middle1148=== RUN TestIsValidCachePath/invalid_char_e1149=== PAUSE TestIsValidCachePath/invalid_char_e1150=== RUN TestIsValidCachePath/invalid_char_u1151=== PAUSE TestIsValidCachePath/invalid_char_u1152=== RUN TestIsValidCachePath/random_path1153=== PAUSE TestIsValidCachePath/random_path1154=== RUN TestIsValidCachePath/empty1155=== PAUSE TestIsValidCachePath/empty1156=== RUN TestIsValidCachePath/leading_slash1157=== PAUSE TestIsValidCachePath/leading_slash1158=== RUN TestIsValidCachePath/wrong_extension1159=== PAUSE TestIsValidCachePath/wrong_extension1160=== RUN TestIsValidCachePath/short_hash1161=== PAUSE TestIsValidCachePath/short_hash1162=== CONT TestGCAdvisoryLockBlocksConcurrentRun1163--- PASS: TestFailedS3DeleteKeepsTombstone (0.44s)1164=== CONT TestPresentRefreshesOnlyStaleClosures11652026/10/14 16:45:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11662026/10/14 16:45:01 INFO Received uploads request method=POST path=/api/pending_closures11672026/10/14 16:45:01 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NzJkOTc2NTAtZDViNi00ODg4LWFhNWQtZGQxMzBmNDA4YWQ3LjUwMTQ5YWVjLTY3MTgtNGJlNS04MWVkLTJiY2JjOTIyYjczNHgxNzkxOTk2MzAwODQ4MDYxMzk3 error="Get \"http://127.0.0.1:1/bucket12/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11682026/10/14 16:45:01 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NzJkOTc2NTAtZDViNi00ODg4LWFhNWQtZGQxMzBmNDA4YWQ3LmY4ZjYzYWUzLTNiZjAtNDA1ZC04NzZkLTljMWVjYzcxNjQ2OHgxNzkxOTk2MzAwODQxMjUzNTc2 parts=121169=== NAME TestNARDeduplicationMetadataUploadBug1170 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1435703015/001/store/5xvc5s2yqwms7hba7fb27pggxfk40ajp-file1.txt11712026/10/14 16:45:01 INFO Received cleanup request method=DELETE path=/api/pending_closures11722026/10/14 16:45:01 INFO Aborted multipart uploads count=1 kept=01173--- PASS: TestReadRedirectNar (0.35s)1174=== CONT TestPresentReportsOnlyClosureRoots1175--- PASS: TestRedundantMultipartUpload (1.29s)1176=== CONT TestLeadEndsOnShutdown1177--- PASS: TestReadProxyDisabled (0.35s)1178=== CONT TestPresentNotReportedWhileGCDeletesClosure1179=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1180=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1181=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1182=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1183=== CONT TestLeadIncumbentAnnouncesAtOnce11842026/10/14 16:45:01 INFO Aborted multipart uploads count=0 kept=011852026/10/14 16:45:01 WARN Force mode enabled - objects will be deleted immediately without grace period11862026/10/14 16:45:01 INFO Received uploads request method=POST path=/api/pending_closures11872026/10/14 16:45:01 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=011882026/10/14 16:45:01 INFO Vacuumed table table=pending_closures11892026/10/14 16:45:01 INFO Vacuumed table table=pending_objects11902026/10/14 16:45:01 INFO Vacuumed table table=multipart_uploads11912026/10/14 16:45:01 INFO Vacuumed table table=closures1192--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.38s)1193=== CONT TestReadProxy40411942026/10/14 16:45:01 INFO Vacuumed table table=objects1195--- PASS: TestGCSweepDeliversEachKeyOnce (0.42s)1196=== CONT TestReadProxyNarinfoAlreadyDecompressed11972026/10/14 16:45:01 INFO Received push request method=POST path=/api/pushes11982026/10/14 16:45:01 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11992026/10/14 16:45:01 INFO Uploading 5xvc5s2yqwms7hba7fb27pggxfk40ajp-file1.txt (160B)12002026/10/14 16:45:01 WARN Failed to register uploaded object key=5xvc5s2yqwms7hba7fb27pggxfk40ajp.ls error="server returned 404: 404 page not found\n"12012026/10/14 16:45:01 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12022026/10/14 16:45:01 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12032026/10/14 16:45:01 INFO Signed narinfos id=1 count=112042026/10/14 16:45:01 INFO Uploading 1 narinfos12052026/10/14 16:45:01 INFO Received complete push request method=POST path=/api/pushes/1/complete1206--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.37s)12072026/10/14 16:45:01 WARN Failed to register uploaded object key=5xvc5s2yqwms7hba7fb27pggxfk40ajp.narinfo error="server returned 404: 404 page not found\n"1208=== CONT TestLeadElectsOneAndHandsOver12092026/10/14 16:45:01 INFO Completed push id=1 objects=3 duration=7.435026ms12102026/10/14 16:45:01 INFO Upload complete. (63ms)1211=== NAME TestNARDeduplicationMetadataUploadBug1212 metadata_upload_test.go:54: Retrieved narinfo from S3:1213 StorePath: /build/TestNARDeduplicationMetadataUploadBug1435703015/001/store/5xvc5s2yqwms7hba7fb27pggxfk40ajp-file1.txt1214 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1215 Compression: zstd1216 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1217 NarSize: 1601218 References: 1219 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1220 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1221 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1222 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12232026/10/14 16:45:01 INFO Received uploads request method=POST path=/api/pending_closures1224--- PASS: TestReadProxyConditionalGet (0.38s)1225=== CONT TestReadProxyInvalidPath1226=== NAME TestNARDeduplicationMetadataUploadBug1227 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1435703015/001/store/wgac62032fhllzaqfwk1mp54q3d00zzl-file2.txt12282026/10/14 16:45:01 INFO Aborted multipart uploads count=0 kept=012292026/10/14 16:45:01 WARN Force mode enabled - objects will be deleted immediately without grace period12302026/10/14 16:45:01 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=012312026/10/14 16:45:01 WARN readiness check failed error="closed pool"1232--- PASS: TestService_readinessHandler (0.36s)1233=== CONT TestConnectWaitsForAPeerMigration12342026/10/14 16:45:01 INFO Vacuumed table table=pending_closures12352026/10/14 16:45:01 INFO Vacuumed table table=pending_objects12362026/10/14 16:45:01 INFO Vacuumed table table=multipart_uploads12372026/10/14 16:45:01 INFO Vacuumed table table=closures12382026/10/14 16:45:01 INFO Vacuumed table table=objects1239--- PASS: TestGCSweepSkipsPendingObjects (0.41s)1240=== CONT TestParseSingleRange1241=== RUN TestParseSingleRange/none1242=== PAUSE TestParseSingleRange/none1243=== RUN TestParseSingleRange/unknown_unit1244=== PAUSE TestParseSingleRange/unknown_unit1245=== RUN TestParseSingleRange/multi-range_ignored1246=== PAUSE TestParseSingleRange/multi-range_ignored1247=== RUN TestParseSingleRange/malformed_no_dash1248=== PAUSE TestParseSingleRange/malformed_no_dash1249=== RUN TestParseSingleRange/malformed_both_empty1250=== PAUSE TestParseSingleRange/malformed_both_empty1251=== RUN TestParseSingleRange/malformed_end_before_start1252=== PAUSE TestParseSingleRange/malformed_end_before_start1253=== RUN TestParseSingleRange/closed1254=== PAUSE TestParseSingleRange/closed1255=== RUN TestParseSingleRange/open-ended1256=== PAUSE TestParseSingleRange/open-ended1257=== RUN TestParseSingleRange/end_clamped_to_size1258=== PAUSE TestParseSingleRange/end_clamped_to_size1259=== RUN TestParseSingleRange/suffix1260=== PAUSE TestParseSingleRange/suffix1261=== RUN TestParseSingleRange/suffix_exceeds_size1262=== PAUSE TestParseSingleRange/suffix_exceeds_size1263=== RUN TestParseSingleRange/single_byte1264=== PAUSE TestParseSingleRange/single_byte1265=== RUN TestParseSingleRange/start_past_EOF1266=== PAUSE TestParseSingleRange/start_past_EOF1267=== RUN TestParseSingleRange/start_far_past_EOF1268=== PAUSE TestParseSingleRange/start_far_past_EOF1269=== CONT TestUploadHandlersRejectInvalidKeys1270=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1271=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1272=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1273=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1274=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1275=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1276=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1277=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1278=== CONT TestResolveDBConnectionString1279=== RUN TestResolveDBConnectionString/flag_wins1280=== PAUSE TestResolveDBConnectionString/flag_wins1281=== RUN TestResolveDBConnectionString/file_when_flag_empty1282=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1283=== RUN TestResolveDBConnectionString/missing_file_is_an_error1284=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1285=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1286=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1287=== RUN TestResolveDBConnectionString/nothing_configured1288=== PAUSE TestResolveDBConnectionString/nothing_configured1289=== CONT TestReadProxyNarStreaming12902026/10/14 16:45:01 INFO Received uploads request method=POST path=/api/pending_closures1291--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.38s)1292=== CONT TestReadProxyHead1293--- PASS: TestService_healthCheckHandler (0.37s)1294=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1295--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.56s)1296=== CONT TestReadProxyContentNegotiation12972026/10/14 16:45:01 INFO Received push request method=POST path=/api/pushes12982026/10/14 16:45:01 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12992026/10/14 16:45:01 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13002026/10/14 16:45:01 INFO Signed narinfos id=2 count=113012026/10/14 16:45:01 WARN Failed to register uploaded object key=wgac62032fhllzaqfwk1mp54q3d00zzl.ls error="server returned 404: 404 page not found\n"13022026/10/14 16:45:01 INFO Uploading 1 narinfos13032026/10/14 16:45:01 INFO Received complete push request method=POST path=/api/pushes/2/complete13042026/10/14 16:45:01 WARN Failed to register uploaded object key=wgac62032fhllzaqfwk1mp54q3d00zzl.narinfo error="server returned 404: 404 page not found\n"13052026/10/14 16:45:01 INFO Completed push id=2 objects=3 duration=2.939407ms13062026/10/14 16:45:01 INFO Upload complete. (54ms)1307=== NAME TestNARDeduplicationMetadataUploadBug1308 metadata_upload_test.go:76: Retrieved narinfo from S3:1309 StorePath: /build/TestNARDeduplicationMetadataUploadBug1435703015/001/store/wgac62032fhllzaqfwk1mp54q3d00zzl-file2.txt1310 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1311 Compression: zstd1312 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1313 NarSize: 1601314 References: 1315 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1316 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1317 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1318 {"version":1,"root":{"type":"regular","size":44}}1319--- PASS: TestNARDeduplicationMetadataUploadBug (0.60s)1320=== CONT TestUploadHandlersRejectOversizedBody1321--- PASS: TestObjectStatsLargeCommit (1.54s)1322=== CONT TestClientCADerivations13232026/10/14 16:45:01 INFO Received uploads request method=POST path=/api/pending_closures13242026/10/14 16:45:01 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1325--- PASS: TestReadProxyNarinfo (0.43s)1326=== CONT TestClientErrorHandling1327=== RUN TestClientErrorHandling/InvalidStorePath1328=== PAUSE TestClientErrorHandling/InvalidStorePath1329=== RUN TestClientErrorHandling/InvalidAuthToken1330=== PAUSE TestClientErrorHandling/InvalidAuthToken1331=== RUN TestClientErrorHandling/ServerNotAvailable1332=== PAUSE TestClientErrorHandling/ServerNotAvailable1333=== CONT TestPendingClosureWriteTimeout1334=== RUN TestPendingClosureWriteTimeout/empty1335=== PAUSE TestPendingClosureWriteTimeout/empty1336=== RUN TestPendingClosureWriteTimeout/400_objects1337=== PAUSE TestPendingClosureWriteTimeout/400_objects1338=== RUN TestPendingClosureWriteTimeout/670k_objects1339=== PAUSE TestPendingClosureWriteTimeout/670k_objects1340=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1341=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1342=== CONT TestCacheStatsHandler1343=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1344=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1345=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1346=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1347=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1348=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1349=== CONT TestClientSharedPathCommittedMidPush13502026/10/14 16:45:01 INFO Aborted multipart uploads count=0 kept=013512026/10/14 16:45:01 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=013522026/10/14 16:45:01 INFO Aborted multipart uploads count=0 kept=013532026/10/14 16:45:01 INFO Vacuumed table table=pending_closures13542026/10/14 16:45:01 INFO Vacuumed table table=pending_objects13552026/10/14 16:45:01 INFO Vacuumed table table=multipart_uploads13562026/10/14 16:45:01 WARN Force mode enabled - objects will be deleted immediately without grace period13572026/10/14 16:45:01 INFO Vacuumed table table=closures13582026/10/14 16:45:01 INFO Vacuumed table table=objects13592026/10/14 16:45:01 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=013602026/10/14 16:45:01 INFO Vacuumed table table=pending_closures13612026/10/14 16:45:01 INFO Vacuumed table table=pending_objects13622026/10/14 16:45:01 INFO Vacuumed table table=multipart_uploads13632026/10/14 16:45:01 INFO Vacuumed table table=closures13642026/10/14 16:45:01 INFO Aborted multipart uploads count=0 kept=013652026/10/14 16:45:01 INFO Vacuumed table table=objects13662026/10/14 16:45:01 WARN Force mode enabled - objects will be deleted immediately without grace period13672026/10/14 16:45:01 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=01368--- PASS: TestGCMetrics (0.52s)1369=== CONT TestCacheConfigHandler1370=== RUN TestCacheConfigHandler/full_config,_no_issuer1371=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1372=== RUN TestCacheConfigHandler/no_cache_url_configured1373=== PAUSE TestCacheConfigHandler/no_cache_url_configured1374=== RUN TestCacheConfigHandler/no_signing_keys1375=== PAUSE TestCacheConfigHandler/no_signing_keys1376=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1377=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1378=== CONT TestPinProtectsFromGC13792026/10/14 16:45:01 INFO Vacuumed table table=pending_closures13802026/10/14 16:45:01 INFO Vacuumed table table=pending_objects13812026/10/14 16:45:01 INFO Vacuumed table table=multipart_uploads13822026/10/14 16:45:01 INFO Vacuumed table table=closures13832026/10/14 16:45:01 INFO Vacuumed table table=objects1384--- PASS: TestPushDedupSurvivesConcurrentGC (0.55s)1385=== CONT TestClientWithDependencies1386--- PASS: TestPresentRefreshesOnlyStaleClosures (0.53s)1387=== CONT TestService_ReadScope_PublicByDefault13882026/10/14 16:45:01 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=nixbld database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1389--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.55s)1390=== CONT TestDeleteClosuresRacingPins13912026/10/14 16:45:01 INFO lead: acquired remote=192.0.2.1:12341392--- PASS: TestPresentReportsOnlyClosureRoots (0.53s)1393=== CONT TestService_RequireScope_OIDC13942026/10/14 16:45:01 INFO lead: acquired remote=192.0.2.1:123413952026/10/14 16:45:01 INFO lead: released remote=192.0.2.1:12341396--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.50s)1397=== CONT TestClientFallsBackToClosures1398--- PASS: TestReadProxy404 (0.52s)1399=== CONT TestService_AuthMiddleware_OIDC1400--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.52s)1401=== CONT TestClientPushesUseOnePush14022026/10/14 16:45:01 INFO lead: acquired remote=192.0.2.1:12341403--- PASS: TestReadProxyInvalidPath (0.48s)1404=== CONT TestService_ReadAuthMiddleware1405--- PASS: TestReadProxyNarStreaming (0.48s)1406=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14072026/10/14 16:45:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35489/oidc1408--- PASS: TestGCBugBareHashReferences (0.74s)1409=== CONT TestService_AuthMiddleware_MTLSProxyHeader1410--- PASS: TestReadProxyHead (0.48s)1411=== CONT TestClientMultipleUploads14122026/10/14 16:45:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34343/oidc1413--- PASS: TestCacheStatsHandler (0.42s)1414=== CONT TestClientIntegration1415--- PASS: TestReadProxyContentNegotiation (0.59s)1416=== CONT TestIsValidUploadKey1417=== RUN TestIsValidUploadKey/narinfo1418=== PAUSE TestIsValidUploadKey/narinfo1419=== RUN TestIsValidUploadKey/nar_zst1420=== PAUSE TestIsValidUploadKey/nar_zst1421=== RUN TestIsValidUploadKey/nar_xz1422=== PAUSE TestIsValidUploadKey/nar_xz1423=== RUN TestIsValidUploadKey/nar_plain1424=== PAUSE TestIsValidUploadKey/nar_plain1425=== RUN TestIsValidUploadKey/listing1426=== PAUSE TestIsValidUploadKey/listing1427=== RUN TestIsValidUploadKey/build_log1428=== PAUSE TestIsValidUploadKey/build_log1429=== RUN TestIsValidUploadKey/build_log_home-manager_file1430=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1431=== RUN TestIsValidUploadKey/build_log_plus_in_name1432=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1433=== RUN TestIsValidUploadKey/build_log_question_mark1434=== PAUSE TestIsValidUploadKey/build_log_question_mark1435=== RUN TestIsValidUploadKey/build_log_equals1436=== PAUSE TestIsValidUploadKey/build_log_equals1437=== RUN TestIsValidUploadKey/realisation1438=== PAUSE TestIsValidUploadKey/realisation1439=== RUN TestIsValidUploadKey/realisation_plus_in_output1440=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1441=== RUN TestIsValidUploadKey/nix-cache-info1442=== PAUSE TestIsValidUploadKey/nix-cache-info1443=== RUN TestIsValidUploadKey/index.html1444=== PAUSE TestIsValidUploadKey/index.html1445=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1446=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1447=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1448=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1449=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1450=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1451=== RUN TestIsValidUploadKey/traversal1452=== PAUSE TestIsValidUploadKey/traversal1453=== RUN TestIsValidUploadKey/traversal_nar1454=== PAUSE TestIsValidUploadKey/traversal_nar1455=== RUN TestIsValidUploadKey/absolute1456=== PAUSE TestIsValidUploadKey/absolute1457=== RUN TestIsValidUploadKey/empty_key1458=== PAUSE TestIsValidUploadKey/empty_key1459=== RUN TestIsValidUploadKey/unknown_type1460=== PAUSE TestIsValidUploadKey/unknown_type1461=== CONT TestGCEndsOnShutdown/before_the_run1462=== NAME TestClientCADerivations1463 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations244192890/001/store/0nh8kb0hprlr61n4m47wcyi6bfvmfkxx-ca-test1464--- PASS: TestService_ReadScope_PublicByDefault (0.35s)1465=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1466=== NAME TestClientCADerivations1467 client_ca_test.go:139: Found 1 dependencies (including self)1468=== NAME TestPinProtectsFromGC1469 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC3319057367/001/store/ya3jnyrprf6ppd3pfhzd9rpv4a5b06fi-pinned-file.txt1470 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC3319057367/001/store/mbbsqbl46csfwvnn9d95shaynmbcm5xz-unpinned-file.txt14712026/10/14 16:45:02 INFO Received push request method=POST path=/api/pushes1472=== NAME TestClientWithDependencies1473 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies4211758952/001/store/cyhs25pmxlgn5vr9flhqdyxqblh7zlqq-test-script14742026/10/14 16:45:02 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14752026/10/14 16:45:02 INFO Uploading p6179mmrrnm2xz0pikc7sxgh252qda7y-top (224B)14762026/10/14 16:45:02 INFO Uploading nci82d73kbrd7hzrg2vshff5w47k0xgx-shared-dep (136B)14772026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/0i44swp5ayg4l1rz50i4zww81ypvkz1ivadd92lsmspbjh7g1c4k.nar.zst error="server returned 404: 404 page not found\n"14782026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14792026/10/14 16:45:02 WARN Failed to register uploaded object key=p6179mmrrnm2xz0pikc7sxgh252qda7y.ls error="server returned 404: 404 page not found\n"14802026/10/14 16:45:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14812026/10/14 16:45:02 WARN Failed to register uploaded object key=nci82d73kbrd7hzrg2vshff5w47k0xgx.ls error="server returned 404: 404 page not found\n"14822026/10/14 16:45:02 INFO Signed narinfos id=1 count=214832026/10/14 16:45:02 INFO Uploading 2 narinfos14842026/10/14 16:45:02 WARN Failed to register uploaded object key=nci82d73kbrd7hzrg2vshff5w47k0xgx.narinfo error="server returned 404: 404 page not found\n"14852026/10/14 16:45:02 INFO Received complete push request method=POST path=/api/pushes/1/complete14862026/10/14 16:45:02 WARN Failed to register uploaded object key=p6179mmrrnm2xz0pikc7sxgh252qda7y.narinfo error="server returned 404: 404 page not found\n"1487--- PASS: TestService_ReadAuthMiddleware (0.28s)1488=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete14892026/10/14 16:45:02 INFO Completed push id=1 objects=6 duration=6.964382ms14902026/10/14 16:45:02 INFO Upload complete. (61ms)1491=== NAME TestClientSharedPathCommittedMidPush1492 client_integration_test.go:680: Retrieved narinfo from S3:1493 StorePath: /build/TestClientSharedPathCommittedMidPush3608112010/001/store/nci82d73kbrd7hzrg2vshff5w47k0xgx-shared-dep1494 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1495 Compression: zstd1496 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821497 NarSize: 1361498 References: 1499 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1500=== NAME TestClientWithDependencies1501 client_integration_test.go:615: Found 1 dependencies (including self)1502=== NAME TestClientSharedPathCommittedMidPush1503 client_integration_test.go:680: Retrieved narinfo from S3:1504 StorePath: /build/TestClientSharedPathCommittedMidPush3608112010/001/store/p6179mmrrnm2xz0pikc7sxgh252qda7y-top1505 URL: nar/0i44swp5ayg4l1rz50i4zww81ypvkz1ivadd92lsmspbjh7g1c4k.nar.zst1506 Compression: zstd1507 NarHash: sha256:0i44swp5ayg4l1rz50i4zww81ypvkz1ivadd92lsmspbjh7g1c4k1508 NarSize: 2241509 References: /build/TestClientSharedPathCommittedMidPush3608112010/001/store/nci82d73kbrd7hzrg2vshff5w47k0xgx-shared-dep1510 CA: text:sha256:0myjlrp2y1fmp2x8v1njc855n6mk5w88jfsr5x7r0hdqicqg41nx1511--- PASS: TestClientSharedPathCommittedMidPush (0.52s)1512=== CONT TestProxyWriteTimeout/narinfo1513=== CONT TestProxyWriteTimeout/unknown_size1514=== CONT TestProxyWriteTimeout/10_GiB_nar1515=== CONT TestProxyWriteTimeout/1_GiB_nar1516--- PASS: TestProxyWriteTimeout (0.01s)1517 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1518 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1519 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1520 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1521=== CONT TestPush_RejectsBadRequests/bad_root15222026/10/14 16:45:02 INFO Received push request method=POST path=/api/pushes1523=== CONT TestPush_RejectsBadRequests/no_roots15242026/10/14 16:45:02 INFO Received push request method=POST path=/api/pushes1525=== CONT TestPush_RejectsBadRequests/no_objects15262026/10/14 16:45:02 INFO Received push request method=POST path=/api/pushes1527=== CONT TestPush_RejectsBadRequests/root_not_in_objects15282026/10/14 16:45:02 INFO Received push request method=POST path=/api/pushes1529=== CONT TestServerTLSConfig/no_client_CA1530--- PASS: TestPush_RejectsBadRequests (0.44s)1531 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1532 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1533 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1534 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1535=== CONT TestServerTLSConfig/not_a_PEM_file1536=== CONT TestServerTLSConfig/missing_CA_file1537--- PASS: TestServerTLSConfig (0.00s)1538 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1539 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1540 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1541=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows15422026/10/14 16:45:02 INFO Received push request method=POST path=/api/pushes15432026/10/14 16:45:02 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15442026/10/14 16:45:02 WARN mTLS auth: bound subjects configured but subject DN unavailable15452026/10/14 16:45:02 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1546--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.28s)1547=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check15482026/10/14 16:45:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15492026/10/14 16:45:02 INFO Uploading ya3jnyrprf6ppd3pfhzd9rpv4a5b06fi-pinned-file.txt (128B)1550--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.73s)1551=== CONT TestIsValidCachePath/narinfo1552=== CONT TestIsValidCachePath/index.html1553=== CONT TestIsValidCachePath/short_hash1554=== CONT TestIsValidCachePath/wrong_extension1555=== CONT TestIsValidCachePath/leading_slash1556=== CONT TestIsValidCachePath/empty1557=== CONT TestIsValidCachePath/random_path1558=== CONT TestIsValidCachePath/invalid_char_u1559=== CONT TestIsValidCachePath/traversal_parent1560=== CONT TestIsValidCachePath/invalid_char_e1561=== CONT TestIsValidCachePath/nar_uncompressed1562=== CONT TestIsValidCachePath/nix-cache-info1563=== CONT TestIsValidCachePath/realisation1564=== CONT TestIsValidCachePath/traversal_in_middle1565=== CONT TestIsValidCachePath/log1566=== CONT TestIsValidCachePath/ls1567=== CONT TestIsValidCachePath/nar_xz1568=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1569=== CONT TestIsValidCachePath/nar_bz21570=== CONT TestIsValidCachePath/nar_zst1571--- PASS: TestIsValidCachePath (0.00s)1572 --- PASS: TestIsValidCachePath/narinfo (0.00s)1573 --- PASS: TestIsValidCachePath/index.html (0.00s)1574 --- PASS: TestIsValidCachePath/short_hash (0.00s)1575 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1576 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1577 --- PASS: TestIsValidCachePath/empty (0.00s)1578 --- PASS: TestIsValidCachePath/random_path (0.00s)1579 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1580 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1581 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1582 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1583 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1584 --- PASS: TestIsValidCachePath/realisation (0.00s)1585 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1586 --- PASS: TestIsValidCachePath/log (0.00s)1587 --- PASS: TestIsValidCachePath/ls (0.00s)1588 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1589 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1590 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1591 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1592=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale15932026/10/14 16:45:02 WARN Failed to register uploaded object key=ya3jnyrprf6ppd3pfhzd9rpv4a5b06fi.ls error="server returned 404: 404 page not found\n"15942026/10/14 16:45:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15952026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"15962026/10/14 16:45:02 INFO Signed narinfos id=1 count=115972026/10/14 16:45:02 INFO Uploading 1 narinfos15982026/10/14 16:45:02 INFO Received complete push request method=POST path=/api/pushes/1/complete15992026/10/14 16:45:02 WARN Failed to register uploaded object key=ya3jnyrprf6ppd3pfhzd9rpv4a5b06fi.narinfo error="server returned 404: 404 page not found\n"16002026/10/14 16:45:02 INFO Completed push id=1 objects=3 duration=6.221135ms16012026/10/14 16:45:02 INFO Upload complete. (63ms)16022026/10/14 16:45:02 INFO Received push request method=POST path=/api/pushes16032026/10/14 16:45:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16042026/10/14 16:45:02 INFO Uploading 0nh8kb0hprlr61n4m47wcyi6bfvmfkxx-ca-test (144B)16052026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16062026/10/14 16:45:02 WARN Failed to register uploaded object key=0nh8kb0hprlr61n4m47wcyi6bfvmfkxx.ls error="server returned 404: 404 page not found\n"16072026/10/14 16:45:02 WARN Failed to register uploaded object key=log/nsksnqkxa3cb5qx2jqgk1p6i64qi7kxp-ca-test.drv error="server returned 404: 404 page not found\n"16082026/10/14 16:45:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16092026/10/14 16:45:02 INFO Signed narinfos id=1 count=116102026/10/14 16:45:02 INFO Uploading 1 narinfos1611--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.30s)1612=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh16132026/10/14 16:45:02 INFO Received complete push request method=POST path=/api/pushes/1/complete16142026/10/14 16:45:02 WARN Failed to register uploaded object key=0nh8kb0hprlr61n4m47wcyi6bfvmfkxx.narinfo error="server returned 404: 404 page not found\n"1615=== RUN TestService_RequireScope_OIDC/builder_may_write1616=== PAUSE TestService_RequireScope_OIDC/builder_may_write1617=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1618=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1619=== RUN TestService_RequireScope_OIDC/ops_may_admin1620=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1621=== RUN TestService_RequireScope_OIDC/ops_may_not_write1622=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1623=== RUN TestService_RequireScope_OIDC/reader_may_not_write1624=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1625=== RUN TestService_RequireScope_OIDC/static_token_may_admin1626=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1627=== RUN TestService_RequireScope_OIDC/static_token_may_write1628=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1629=== RUN TestService_RequireScope_OIDC/reader_may_read1630=== PAUSE TestService_RequireScope_OIDC/reader_may_read1631=== RUN TestService_RequireScope_OIDC/writer_implies_read1632=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1633=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1634=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1635=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1636=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1637=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1638=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1639=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1640=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1641=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1642=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1643=== CONT TestParseSingleRange/none1644=== CONT TestParseSingleRange/closed1645=== CONT TestParseSingleRange/malformed_end_before_start1646=== CONT TestParseSingleRange/malformed_both_empty1647=== CONT TestParseSingleRange/open-ended1648=== CONT TestParseSingleRange/multi-range_ignored1649=== CONT TestParseSingleRange/start_past_EOF1650=== CONT TestParseSingleRange/start_far_past_EOF1651=== CONT TestParseSingleRange/single_byte1652=== CONT TestParseSingleRange/unknown_unit1653=== CONT TestParseSingleRange/malformed_no_dash1654=== CONT TestParseSingleRange/suffix_exceeds_size1655=== CONT TestParseSingleRange/suffix1656=== CONT TestParseSingleRange/end_clamped_to_size1657--- PASS: TestParseSingleRange (0.00s)1658 --- PASS: TestParseSingleRange/none (0.00s)1659 --- PASS: TestParseSingleRange/closed (0.00s)1660 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1661 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1662 --- PASS: TestParseSingleRange/open-ended (0.00s)1663 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1664 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1665 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1666 --- PASS: TestParseSingleRange/single_byte (0.00s)1667 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1668 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1669 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1670 --- PASS: TestParseSingleRange/suffix (0.00s)1671 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1672=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16732026/10/14 16:45:02 INFO Received uploads request method=POST path=/1674=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16752026/10/14 16:45:02 INFO Received complete multipart upload request method=POST path=/1676=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16772026/10/14 16:45:02 INFO Received uploads request method=POST path=/1678=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16792026/10/14 16:45:02 INFO Received request for more parts method=POST path=/1680--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1681 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1682 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1683 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1684 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1685=== CONT TestResolveDBConnectionString/flag_wins1686=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1687=== CONT TestResolveDBConnectionString/missing_file_is_an_error1688=== CONT TestResolveDBConnectionString/file_when_flag_empty1689=== CONT TestResolveDBConnectionString/nothing_configured1690=== CONT TestClientErrorHandling/InvalidStorePath1691--- PASS: TestResolveDBConnectionString (0.00s)1692 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1693 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1694 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1695 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1696 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)16972026/10/14 16:45:02 INFO Completed push id=1 objects=4 duration=9.163282ms16982026/10/14 16:45:02 INFO Upload complete. (107ms)16992026/10/14 16:45:02 INFO Received push request method=POST path=/api/pushes1700=== NAME TestClientCADerivations1701 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations244192890/001/store/0nh8kb0hprlr61n4m47wcyi6bfvmfkxx-ca-test1702 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1703 Compression: zstd1704 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1705 NarSize: 1441706 References: 1707 Deriver: /build/TestClientCADerivations244192890/001/store/nsksnqkxa3cb5qx2jqgk1p6i64qi7kxp-ca-test.drv1708 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1709 client_ca_test.go:185: Checking for realisation files in S3...1710 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations17112026/10/14 16:45:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1712 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache17132026/10/14 16:45:02 INFO Uploading cyhs25pmxlgn5vr9flhqdyxqblh7zlqq-test-script (136B)17142026/10/14 16:45:02 WARN Failed to register uploaded object key=log/vwd2mrfx5l6bm3d0br2fd5lzl1nyhw12-test-script.drv error="server returned 404: 404 page not found\n"17152026/10/14 16:45:02 WARN Failed to register uploaded object key=cyhs25pmxlgn5vr9flhqdyxqblh7zlqq.ls error="server returned 404: 404 page not found\n"17162026/10/14 16:45:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17172026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17182026/10/14 16:45:02 INFO Signed narinfos id=1 count=117192026/10/14 16:45:02 INFO Uploading 1 narinfos17202026/10/14 16:45:02 INFO Received complete push request method=POST path=/api/pushes/1/complete17212026/10/14 16:45:02 WARN Failed to register uploaded object key=cyhs25pmxlgn5vr9flhqdyxqblh7zlqq.narinfo error="server returned 404: 404 page not found\n"17222026/10/14 16:45:02 INFO Completed push id=1 objects=4 duration=7.631448ms17232026/10/14 16:45:02 INFO Upload complete. (58ms)1724=== NAME TestClientWithDependencies1725 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies4211758952/001/store) requires matching store prefix1726--- PASS: TestClientWithDependencies (0.56s)1727=== CONT TestClientErrorHandling/ServerNotAvailable1728=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1729=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1730=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1731=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1732=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1733=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1734=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1735=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1736=== CONT TestClientErrorHandling/InvalidAuthToken17372026/10/14 16:45:02 INFO Received push request method=POST path=/api/pushes17382026/10/14 16:45:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17392026/10/14 16:45:02 INFO Uploading mbbsqbl46csfwvnn9d95shaynmbcm5xz-unpinned-file.txt (128B)17402026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17412026/10/14 16:45:02 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17422026/10/14 16:45:02 INFO Signed narinfos id=2 count=117432026/10/14 16:45:02 WARN Failed to register uploaded object key=mbbsqbl46csfwvnn9d95shaynmbcm5xz.ls error="server returned 404: 404 page not found\n"17442026/10/14 16:45:02 INFO Uploading 1 narinfos17452026/10/14 16:45:02 INFO Received complete push request method=POST path=/api/pushes/2/complete17462026/10/14 16:45:02 WARN Failed to register uploaded object key=mbbsqbl46csfwvnn9d95shaynmbcm5xz.narinfo error="server returned 404: 404 page not found\n"17472026/10/14 16:45:02 INFO Completed push id=2 objects=3 duration=2.412342ms17482026/10/14 16:45:02 INFO Upload complete. (52ms)1749=== NAME TestClientMultipleUploads1750 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads413507810/001/store/d1pjfpi0qkyyaxnxs986h70dbn1b8q54-test-file-0.txt17512026/10/14 16:45:02 INFO Received uploads request method=POST path=/api/pending_closures17522026/10/14 16:45:02 INFO Received uploads request method=POST path=/api/pending_closures17532026/10/14 16:45:02 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17542026/10/14 16:45:02 INFO Uploading aw82vjq5ni8iv5pchbpa4w42qj1bg5fr-shared-dep (136B)17552026/10/14 16:45:02 INFO Uploading l50a1ff1jwgd69cjjpsh10dzdz8vywah-b (216B)17562026/10/14 16:45:02 WARN Failed to register uploaded object key=jxvzz62jbha0a26ffsc12hymanadvxvf.ls error="server returned 404: 404 page not found\n"17572026/10/14 16:45:02 WARN Failed to register uploaded object key=aw82vjq5ni8iv5pchbpa4w42qj1bg5fr.ls error="server returned 404: 404 page not found\n"17582026/10/14 16:45:02 WARN Failed to register uploaded object key=l50a1ff1jwgd69cjjpsh10dzdz8vywah.ls error="server returned 404: 404 page not found\n"17592026/10/14 16:45:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17602026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/005valx09xp6i6jw5dh4ml5wfcnm2fxmllg1xvab4bljvx6k4isp.nar.zst error="server returned 404: 404 page not found\n"17612026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17622026/10/14 16:45:02 INFO Signed narinfos id=1 count=217632026/10/14 16:45:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17642026/10/14 16:45:02 INFO Signed narinfos id=2 count=217652026/10/14 16:45:02 INFO Uploading 4 narinfos17662026/10/14 16:45:02 WARN Failed to register uploaded object key=l50a1ff1jwgd69cjjpsh10dzdz8vywah.narinfo error="server returned 404: 404 page not found\n"17672026/10/14 16:45:02 WARN Failed to register uploaded object key=jxvzz62jbha0a26ffsc12hymanadvxvf.narinfo error="server returned 404: 404 page not found\n"17682026/10/14 16:45:02 WARN Failed to register uploaded object key=aw82vjq5ni8iv5pchbpa4w42qj1bg5fr.narinfo error="server returned 404: 404 page not found\n"17692026/10/14 16:45:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17702026/10/14 16:45:02 WARN Failed to register uploaded object key=aw82vjq5ni8iv5pchbpa4w42qj1bg5fr.narinfo error="server returned 404: 404 page not found\n"1771=== NAME TestOrphanedObjectsGCStressTest1772 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains17732026/10/14 16:45:02 INFO Starting cleanup of old closures method=DELETE path=/api/closures17742026/10/14 16:45:02 INFO Garbage collection started1775=== NAME TestClientMultipleUploads1776 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads413507810/001/store/19wh7dg8vd0vwiqga82iggwm0q43b9wq-test-file-1.txt1777=== CONT TestPendingClosureWriteTimeout/empty1778=== CONT TestPendingClosureWriteTimeout/670k_objects1779=== CONT TestPendingClosureWriteTimeout/400_objects1780=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline17812026/10/14 16:45:02 INFO Completed upload id=1 objects=6 duration=6.769481ms17822026/10/14 16:45:02 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17832026/10/14 16:45:02 INFO Completed upload id=2 objects=6 duration=1.483813ms17842026/10/14 16:45:02 INFO Upload complete. (67ms)1785=== NAME TestClientFallsBackToClosures1786 client_pushes_test.go:112: Retrieved narinfo from S3:1787 StorePath: /build/TestClientFallsBackToClosures869092949/001/store/aw82vjq5ni8iv5pchbpa4w42qj1bg5fr-shared-dep1788 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1789 Compression: zstd1790 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821791 NarSize: 1361792 References: 1793 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1794 client_pushes_test.go:112: Retrieved narinfo from S3:1795 StorePath: /build/TestClientFallsBackToClosures869092949/001/store/jxvzz62jbha0a26ffsc12hymanadvxvf-a1796 URL: nar/005valx09xp6i6jw5dh4ml5wfcnm2fxmllg1xvab4bljvx6k4isp.nar.zst1797 Compression: zstd1798 NarHash: sha256:005valx09xp6i6jw5dh4ml5wfcnm2fxmllg1xvab4bljvx6k4isp1799 NarSize: 2161800 References: /build/TestClientFallsBackToClosures869092949/001/store/aw82vjq5ni8iv5pchbpa4w42qj1bg5fr-shared-dep1801 CA: text:sha256:18fqravkni6zz645vav85675dlhjf4j66ljgp6vqh6ss87r4dh391802=== NAME TestClientCADerivations1803 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1804 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1805 error: binary cache 's3://bucket75?endpoint=http://localhost:42493®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations244192890/001/store'1806 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 118072026/10/14 16:45:02 INFO Received push request method=POST path=/api/pushes18082026/10/14 16:45:02 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1809=== NAME TestClientFallsBackToClosures1810 client_pushes_test.go:112: Retrieved narinfo from S3:1811 StorePath: /build/TestClientFallsBackToClosures869092949/001/store/l50a1ff1jwgd69cjjpsh10dzdz8vywah-b1812 URL: nar/005valx09xp6i6jw5dh4ml5wfcnm2fxmllg1xvab4bljvx6k4isp.nar.zst1813 Compression: zstd1814 NarHash: sha256:005valx09xp6i6jw5dh4ml5wfcnm2fxmllg1xvab4bljvx6k4isp1815 NarSize: 2161816 References: /build/TestClientFallsBackToClosures869092949/001/store/aw82vjq5ni8iv5pchbpa4w42qj1bg5fr-shared-dep1817 CA: text:sha256:18fqravkni6zz645vav85675dlhjf4j66ljgp6vqh6ss87r4dh3918182026/10/14 16:45:02 INFO Aborted multipart uploads count=0 kept=01819--- PASS: TestClientCADerivations (0.82s)1820=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18212026/10/14 16:45:02 INFO Received uploads request method=POST path=/18222026/10/14 16:45:02 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18232026/10/14 16:45:02 INFO Uploading iqbialvmpcifl0647q14kibmkv8m2h6q-shared-dep (136B)18242026/10/14 16:45:02 INFO Uploading 6sz2zra9lp7baf1x4lb73sbgpbfnbc0h-b (216B)1825--- PASS: TestClientFallsBackToClosures (0.54s)1826=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18272026/10/14 16:45:02 INFO Received complete multipart upload request method=POST path=/1828=== NAME TestClientIntegration1829 client_integration_test.go:286: Created store path: /build/TestClientIntegration865618619/002/store/kwk0yv6sa3ppn6v5sb1cwzvva9h3hhl3-test-file.txt18302026/10/14 16:45:02 WARN Force mode enabled - objects will be deleted immediately without grace period18312026/10/14 16:45:02 WARN Failed to register uploaded object key=0h2y3fhby19565pmp87adxmg7nqclx3y.ls error="server returned 404: 404 page not found\n"18322026/10/14 16:45:02 WARN Failed to register uploaded object key=6sz2zra9lp7baf1x4lb73sbgpbfnbc0h.ls error="server returned 404: 404 page not found\n"18332026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18342026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/1l8wqfvrfcily4gknf6gs0n5kwxxnb9znc2v8ia6839agsl5zbxl.nar.zst error="server returned 404: 404 page not found\n"18352026/10/14 16:45:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18362026/10/14 16:45:02 WARN Failed to register uploaded object key=iqbialvmpcifl0647q14kibmkv8m2h6q.ls error="server returned 404: 404 page not found\n"18372026/10/14 16:45:02 INFO Signed narinfos id=1 count=318382026/10/14 16:45:02 INFO Uploading 3 narinfos1839=== NAME TestOrphanedObjectsGCStressTest1840 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion18412026/10/14 16:45:02 WARN Failed to register uploaded object key=6sz2zra9lp7baf1x4lb73sbgpbfnbc0h.narinfo error="server returned 404: 404 page not found\n"18422026/10/14 16:45:02 WARN Failed to register uploaded object key=0h2y3fhby19565pmp87adxmg7nqclx3y.narinfo error="server returned 404: 404 page not found\n"18432026/10/14 16:45:02 INFO Received complete push request method=POST path=/api/pushes/1/complete18442026/10/14 16:45:02 WARN Failed to register uploaded object key=iqbialvmpcifl0647q14kibmkv8m2h6q.narinfo error="server returned 404: 404 page not found\n"18452026/10/14 16:45:02 INFO Completed push id=1 objects=8 duration=6.603498ms18462026/10/14 16:45:02 INFO Upload complete. (65ms)18472026/10/14 16:45:02 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=01848=== NAME TestClientPushesUseOnePush1849 client_pushes_test.go:97: Retrieved narinfo from S3:1850 StorePath: /build/TestClientPushesUseOnePush2650099487/001/store/iqbialvmpcifl0647q14kibmkv8m2h6q-shared-dep1851 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1852 Compression: zstd1853 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821854 NarSize: 1361855 References: 1856 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n18572026/10/14 16:45:02 INFO Vacuumed table table=pending_closures1858 client_pushes_test.go:97: Retrieved narinfo from S3:1859 StorePath: /build/TestClientPushesUseOnePush2650099487/001/store/0h2y3fhby19565pmp87adxmg7nqclx3y-a1860 URL: nar/1l8wqfvrfcily4gknf6gs0n5kwxxnb9znc2v8ia6839agsl5zbxl.nar.zst1861 Compression: zstd1862 NarHash: sha256:1l8wqfvrfcily4gknf6gs0n5kwxxnb9znc2v8ia6839agsl5zbxl1863 NarSize: 2161864 References: /build/TestClientPushesUseOnePush2650099487/001/store/iqbialvmpcifl0647q14kibmkv8m2h6q-shared-dep1865 CA: text:sha256:148yq608p8ka30wy4hrs81rjg9rf6r80v3hpr041xdxi2xs2v1hm18662026/10/14 16:45:02 INFO Aborted multipart uploads count=0 kept=01867=== NAME TestClientMultipleUploads1868 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads413507810/001/store/w3k01g3f46lcbbyym7j70dykjz4jnkj2-test-file-2.txt18692026/10/14 16:45:02 INFO Vacuumed table table=pending_objects18702026/10/14 16:45:02 INFO Vacuumed table table=multipart_uploads1871=== NAME TestClientPushesUseOnePush1872 client_pushes_test.go:97: Retrieved narinfo from S3:1873 StorePath: /build/TestClientPushesUseOnePush2650099487/001/store/6sz2zra9lp7baf1x4lb73sbgpbfnbc0h-b1874 URL: nar/1l8wqfvrfcily4gknf6gs0n5kwxxnb9znc2v8ia6839agsl5zbxl.nar.zst1875 Compression: zstd1876 NarHash: sha256:1l8wqfvrfcily4gknf6gs0n5kwxxnb9znc2v8ia6839agsl5zbxl1877 NarSize: 2161878 References: /build/TestClientPushesUseOnePush2650099487/001/store/iqbialvmpcifl0647q14kibmkv8m2h6q-shared-dep1879 CA: text:sha256:148yq608p8ka30wy4hrs81rjg9rf6r80v3hpr041xdxi2xs2v1hm18802026/10/14 16:45:02 INFO Vacuumed table table=closures18812026/10/14 16:45:02 WARN Force mode enabled - objects will be deleted immediately without grace period18822026/10/14 16:45:02 INFO Vacuumed table table=objects1883--- PASS: TestClientPushesUseOnePush (0.52s)1884=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18852026/10/14 16:45:02 INFO Received request for more parts method=POST path=/1886=== CONT TestCacheConfigHandler/full_config,_no_issuer18872026/10/14 16:45:02 INFO Aborted multipart uploads count=0 kept=01888=== CONT TestCacheConfigHandler/no_signing_keys1889=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1890=== CONT TestCacheConfigHandler/no_cache_url_configured1891--- PASS: TestCacheConfigHandler (0.00s)1892 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1893 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1894 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1895 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1896=== CONT TestIsValidUploadKey/narinfo1897=== CONT TestIsValidUploadKey/realisation_plus_in_output1898=== CONT TestIsValidUploadKey/unknown_type1899=== CONT TestIsValidUploadKey/empty_key1900=== CONT TestIsValidUploadKey/absolute1901=== CONT TestIsValidUploadKey/build_log_home-manager_file1902=== CONT TestIsValidUploadKey/traversal_nar1903=== CONT TestIsValidUploadKey/realisation1904=== CONT TestIsValidUploadKey/traversal1905=== CONT TestIsValidUploadKey/build_log_equals1906=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1907=== CONT TestIsValidUploadKey/build_log_question_mark1908=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1909=== CONT TestIsValidUploadKey/build_log_plus_in_name1910=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1911=== CONT TestIsValidUploadKey/index.html1912=== CONT TestIsValidUploadKey/nix-cache-info1913=== CONT TestIsValidUploadKey/nar_plain1914=== CONT TestIsValidUploadKey/nar_zst1915=== CONT TestIsValidUploadKey/build_log1916=== CONT TestIsValidUploadKey/listing1917=== CONT TestIsValidUploadKey/nar_xz1918--- PASS: TestIsValidUploadKey (0.00s)1919 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1920 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1921 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1922 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1923 --- PASS: TestIsValidUploadKey/absolute (0.00s)1924 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1925 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1926 --- PASS: TestIsValidUploadKey/realisation (0.00s)1927 --- PASS: TestIsValidUploadKey/traversal (0.00s)1928 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1929 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1930 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1931 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1932 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1933 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1934 --- PASS: TestIsValidUploadKey/index.html (0.00s)1935 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1936 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1937 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1938 --- PASS: TestIsValidUploadKey/build_log (0.00s)1939 --- PASS: TestIsValidUploadKey/listing (0.00s)1940 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1941=== CONT TestService_RequireScope_OIDC/builder_may_write1942=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1943=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19442026/10/14 16:45:02 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]1945=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1946=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1947=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1948=== CONT TestService_RequireScope_OIDC/writer_implies_read1949=== CONT TestService_RequireScope_OIDC/reader_may_read1950=== CONT TestService_RequireScope_OIDC/static_token_may_write1951=== CONT TestService_RequireScope_OIDC/static_token_may_admin1952=== CONT TestService_RequireScope_OIDC/reader_may_not_write1953=== CONT TestService_RequireScope_OIDC/ops_may_not_write1954=== CONT TestService_RequireScope_OIDC/ops_may_admin1955=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1956=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1957--- PASS: TestService_RequireScope_OIDC (0.44s)1958 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1959 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1960 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1961 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1962 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1963 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1964 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1965 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1966 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1967 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1968 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1969 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1970 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1971 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)19722026/10/14 16:45:02 WARN Force mode enabled - objects will be deleted immediately without grace period1973=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19742026/10/14 16:45:02 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]1975=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19762026/10/14 16:45:02 WARN Authentication failed token_preview=eyJhbGciOi...baffMC8G5A token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1977=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1978--- PASS: TestService_AuthMiddleware_OIDC (0.42s)1979 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1980 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1981 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1982 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)19832026/10/14 16:45:02 INFO Received uploads request method=POST path=/api/pending_closures19842026/10/14 16:45:02 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:42493/bucket93/?delete=\": context canceled"1985--- PASS: TestGCEndsOnShutdown (0.00s)1986 --- PASS: TestGCEndsOnShutdown/before_the_run (0.28s)1987 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.30s)1988 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.23s)19892026/10/14 16:45:02 INFO Aborted multipart uploads count=0 kept=019902026/10/14 16:45:02 WARN Force mode enabled - objects will be deleted immediately without grace period19912026/10/14 16:45:02 INFO Received uploads request method=POST path=/api/pending_closures19922026/10/14 16:45:02 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=019932026/10/14 16:45:02 INFO Vacuumed table table=pending_closures19942026/10/14 16:45:02 INFO Vacuumed table table=pending_objects19952026/10/14 16:45:02 INFO Vacuumed table table=multipart_uploads19962026/10/14 16:45:02 INFO Vacuumed table table=closures19972026/10/14 16:45:02 INFO Received push request method=POST path=/api/pushes19982026/10/14 16:45:02 INFO Vacuumed table table=objects19992026/10/14 16:45:02 INFO Aborted multipart uploads count=0 kept=020002026/10/14 16:45:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20012026/10/14 16:45:02 INFO Uploading kwk0yv6sa3ppn6v5sb1cwzvva9h3hhl3-test-file.txt (152B)20022026/10/14 16:45:02 WARN Force mode enabled - objects will be deleted immediately without grace period20032026/10/14 16:45:02 WARN Failed to register uploaded object key=kwk0yv6sa3ppn6v5sb1cwzvva9h3hhl3.ls error="server returned 404: 404 page not found\n"20042026/10/14 16:45:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20052026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"20062026/10/14 16:45:02 INFO Signed narinfos id=1 count=120072026/10/14 16:45:02 INFO Uploading 1 narinfos20082026/10/14 16:45:02 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=020092026/10/14 16:45:02 INFO Received complete push request method=POST path=/api/pushes/1/complete20102026/10/14 16:45:02 WARN Failed to register uploaded object key=kwk0yv6sa3ppn6v5sb1cwzvva9h3hhl3.narinfo error="server returned 404: 404 page not found\n"20112026/10/14 16:45:02 INFO Vacuumed table table=pending_closures20122026/10/14 16:45:02 INFO Vacuumed table table=pending_objects20132026/10/14 16:45:02 INFO Vacuumed table table=multipart_uploads20142026/10/14 16:45:02 INFO Vacuumed table table=closures20152026/10/14 16:45:02 INFO Vacuumed table table=objects20162026/10/14 16:45:02 INFO Completed push id=1 objects=3 duration=4.745583ms20172026/10/14 16:45:02 WARN Request failed, retrying attempt=2 backoff=185.978721ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20182026/10/14 16:45:02 INFO Upload complete. (59ms)20192026/10/14 16:45:02 INFO Received push request method=POST path=/api/pushes20202026/10/14 16:45:02 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)20212026/10/14 16:45:02 INFO Uploading 19wh7dg8vd0vwiqga82iggwm0q43b9wq-test-file-1.txt (160B)20222026/10/14 16:45:02 INFO Uploading d1pjfpi0qkyyaxnxs986h70dbn1b8q54-test-file-0.txt (160B)20232026/10/14 16:45:02 INFO Uploading w3k01g3f46lcbbyym7j70dykjz4jnkj2-test-file-2.txt (160B)2024--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2025 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.26s)2026 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.27s)20272026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"20282026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"20292026/10/14 16:45:02 WARN Failed to register uploaded object key=19wh7dg8vd0vwiqga82iggwm0q43b9wq.ls error="server returned 404: 404 page not found\n"20302026/10/14 16:45:02 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"20312026/10/14 16:45:02 WARN Failed to register uploaded object key=d1pjfpi0qkyyaxnxs986h70dbn1b8q54.ls error="server returned 404: 404 page not found\n"20322026/10/14 16:45:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20332026/10/14 16:45:02 WARN Failed to register uploaded object key=w3k01g3f46lcbbyym7j70dykjz4jnkj2.ls error="server returned 404: 404 page not found\n"20342026/10/14 16:45:02 INFO Signed narinfos id=1 count=320352026/10/14 16:45:02 INFO Uploading 3 narinfos20362026/10/14 16:45:02 WARN Failed to register uploaded object key=w3k01g3f46lcbbyym7j70dykjz4jnkj2.narinfo error="server returned 404: 404 page not found\n"20372026/10/14 16:45:02 WARN Failed to register uploaded object key=19wh7dg8vd0vwiqga82iggwm0q43b9wq.narinfo error="server returned 404: 404 page not found\n"20382026/10/14 16:45:02 INFO Received complete push request method=POST path=/api/pushes/1/complete20392026/10/14 16:45:02 WARN Failed to register uploaded object key=d1pjfpi0qkyyaxnxs986h70dbn1b8q54.narinfo error="server returned 404: 404 page not found\n"20402026/10/14 16:45:02 INFO Completed push id=1 objects=9 duration=3.945055ms20412026/10/14 16:45:02 INFO Upload complete. (57ms)2042=== NAME TestClientMultipleUploads2043 client_integration_test.go:369: Uploaded 3 paths in 96.242497ms2044--- PASS: TestClientMultipleUploads (0.54s)20452026/10/14 16:45:02 INFO All 1 paths already cached2046=== NAME TestClientIntegration2047 client_integration_test.go:312: Retrieved narinfo from S3:2048 StorePath: /build/TestClientIntegration865618619/002/store/kwk0yv6sa3ppn6v5sb1cwzvva9h3hhl3-test-file.txt2049 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst2050 Compression: zstd2051 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12052 NarSize: 1522053 References: 2054 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk12055 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)2056 client_integration_test.go:313: Decompressed .ls content (64 bytes):2057 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}2058 client_integration_test.go:316: Testing garbage collection...20592026/10/14 16:45:02 INFO Received uploads request method=POST path=/api/pending_closures20602026/10/14 16:45:02 INFO Starting cleanup of old closures method=DELETE path=/api/closures20612026/10/14 16:45:02 INFO Garbage collection started20622026/10/14 16:45:02 INFO Aborted multipart uploads count=0 kept=020632026/10/14 16:45:02 WARN Force mode enabled - objects will be deleted immediately without grace period20642026/10/14 16:45:02 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=020652026/10/14 16:45:02 INFO Vacuumed table table=pending_closures20662026/10/14 16:45:02 INFO Vacuumed table table=pending_objects20672026/10/14 16:45:02 INFO Vacuumed table table=multipart_uploads20682026/10/14 16:45:02 INFO Vacuumed table table=closures20692026/10/14 16:45:02 INFO Vacuumed table table=objects20702026/10/14 16:45:02 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20712026/10/14 16:45:02 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2072=== NAME TestOrphanedObjectsGCStressTest2073 orphaned_objects_gc_test.go:503: Stress test completed successfully:2074 orphaned_objects_gc_test.go:504: - Active objects preserved: 202075 orphaned_objects_gc_test.go:505: - Objects deleted: 2102076 orphaned_objects_gc_test.go:506: - Total GC'd: 2102077--- PASS: TestOrphanedObjectsGCStressTest (2.64s)20782026/10/14 16:45:02 WARN Request failed, retrying attempt=3 backoff=385.57884ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20792026/10/14 16:45:02 INFO lead: released remote=192.0.2.1:12342080--- PASS: TestLeadEndsOnShutdown (1.54s)20812026/10/14 16:45:02 WARN Request failed, retrying attempt=4 backoff=854.869047ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20822026/10/14 16:45:03 INFO lead: released remote=192.0.2.1:12342083--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2084 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.88s)2085 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.91s)20862026/10/14 16:45:03 INFO lead: acquired remote=192.0.2.1:12342087--- PASS: TestPendingClosureWriteTimeout (0.00s)2088 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2089 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2090 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2091 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (0.98s)2092--- PASS: TestUploadHandlersRejectOversizedBody (0.16s)2093 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.05s)2094 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)2095 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.10s)2096--- PASS: TestDeleteClosuresRacingPins (1.74s)20972026/10/14 16:45:03 WARN Request failed, retrying attempt=5 backoff=1.618473001s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20982026/10/14 16:45:04 WARN Rate limiter enabled after throttle name=s3-test rate=520992026/10/14 16:45:04 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2100=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2101 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102102 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002103--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.20s)21042026/10/14 16:45:04 INFO lead: released remote=192.0.2.1:12342105--- PASS: TestLeadElectsOneAndHandsOver (2.82s)21062026/10/14 16:45:04 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021072026/10/14 16:45:04 INFO Received create pin request method=POST path=/api/pins/myapp21082026/10/14 16:45:04 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC3319057367/001/store/ya3jnyrprf6ppd3pfhzd9rpv4a5b06fi-pinned-file.txt narinfo_key=ya3jnyrprf6ppd3pfhzd9rpv4a5b06fi.narinfo21092026/10/14 16:45:04 INFO Starting cleanup of old closures method=DELETE path=/api/closures21102026/10/14 16:45:04 INFO Garbage collection started21112026/10/14 16:45:04 INFO Aborted multipart uploads count=0 kept=021122026/10/14 16:45:04 WARN Force mode enabled - objects will be deleted immediately without grace period21132026/10/14 16:45:04 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=021142026/10/14 16:45:04 INFO Vacuumed table table=pending_closures21152026/10/14 16:45:04 INFO Vacuumed table table=pending_objects21162026/10/14 16:45:04 INFO Vacuumed table table=multipart_uploads21172026/10/14 16:45:04 INFO Vacuumed table table=closures21182026/10/14 16:45:04 INFO Vacuumed table table=objects21192026/10/14 16:45:04 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02120=== NAME TestClientIntegration2121 client_integration_test.go:323: Objects in database after GC:2122 client_integration_test.go:323: Successfully deleted all objects with GC --force2123--- PASS: TestClientIntegration (2.49s)21242026/10/14 16:45:05 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21252026/10/14 16:45:05 WARN Request failed, retrying attempt=2 backoff=211.938427ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2126--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.54s)21272026/10/14 16:45:05 WARN Request failed, retrying attempt=3 backoff=369.471019ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21282026/10/14 16:45:06 WARN Request failed, retrying attempt=4 backoff=812.856749ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2129=== NAME TestPinProtectsFromGC2130 client_integration_test.go:840: Pin successfully protected closure from garbage collection2131--- PASS: TestPinProtectsFromGC (4.64s)2132--- PASS: TestConnectWaitsForAPeerMigration (5.14s)21332026/10/14 16:45:06 INFO Aborted multipart uploads count=1 kept=021342026/10/14 16:45:06 INFO Received cleanup request method=DELETE path=/api/pending_closures21352026/10/14 16:45:06 INFO Aborted multipart uploads count=1 kept=02136--- PASS: TestPendingCleanupUsesOneCutoff (6.49s)21372026/10/14 16:45:06 WARN Request failed, retrying attempt=5 backoff=1.461770437s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21382026/10/14 16:45:08 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"21392026/10/14 16:45:08 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21402026/10/14 16:45:08 WARN Request failed, retrying attempt=2 backoff=215.294284ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21412026/10/14 16:45:08 WARN Request failed, retrying attempt=3 backoff=412.959612ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21422026/10/14 16:45:09 WARN Request failed, retrying attempt=4 backoff=860.48114ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21432026/10/14 16:45:10 WARN Request failed, retrying attempt=5 backoff=1.731072776s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21442026/10/14 16:45:11 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21452026/10/14 16:45:11 WARN Request failed, retrying attempt=2 backoff=210.779301ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21462026/10/14 16:45:12 WARN Request failed, retrying attempt=3 backoff=403.213019ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21472026/10/14 16:45:12 WARN Request failed, retrying attempt=4 backoff=791.306866ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21482026/10/14 16:45:13 WARN Request failed, retrying attempt=5 backoff=1.670645847s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2149--- PASS: TestClientErrorHandling (0.00s)2150 --- PASS: TestClientErrorHandling/InvalidStorePath (0.27s)2151 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.31s)2152 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.73s)2153PASS21542026-10-14 16:45:15.219 UTC [129] LOG: received smart shutdown request21552026-10-14 16:45:15.223 UTC [129] LOG: background worker "logical replication launcher" (PID 139) exited with exit code 121562026-10-14 16:45:15.235 UTC [134] LOG: shutting down21572026-10-14 16:45:15.235 UTC [134] LOG: checkpoint starting: shutdown immediate21582026-10-14 16:45:16.094 UTC [134] LOG: checkpoint complete: wrote 10426 buffers (63.6%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.180 s, sync=0.645 s, total=0.860 s; sync files=34045, longest=0.002 s, average=0.001 s; distance=531581 kB, estimate=531581 kB; lsn=0/21E85200, redo lsn=0/21E8520021592026-10-14 16:45:16.171 UTC [129] LOG: database system is shut down2160Running OIDC tests...2161=== RUN TestAudienceForIssuer2162=== PAUSE TestAudienceForIssuer2163=== RUN TestGlobMatch2164=== PAUSE TestGlobMatch2165=== RUN TestValidateToken_ValidToken2166=== PAUSE TestValidateToken_ValidToken2167=== RUN TestValidateToken_WrongAudience2168=== PAUSE TestValidateToken_WrongAudience2169=== RUN TestValidateToken_Expired2170=== PAUSE TestValidateToken_Expired2171=== RUN TestValidateToken_BoundClaimsMismatch2172=== PAUSE TestValidateToken_BoundClaimsMismatch2173=== RUN TestValidateToken_BoundSubjectMismatch2174=== PAUSE TestValidateToken_BoundSubjectMismatch2175=== RUN TestValidateToken_MultipleProviders2176=== PAUSE TestValidateToken_MultipleProviders2177=== RUN TestValidateToken_NoMatchingProvider2178=== PAUSE TestValidateToken_NoMatchingProvider2179=== RUN TestValidateToken_KubernetesServiceAccount2180=== PAUSE TestValidateToken_KubernetesServiceAccount2181=== RUN TestNewValidator_KubernetesRequiresCA2182=== PAUSE TestNewValidator_KubernetesRequiresCA2183=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2184=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2185=== RUN TestPins_ReservedForMatchingRule2186=== PAUSE TestPins_ReservedForMatchingRule2187=== RUN TestPins_TopLevelShorthand2188=== PAUSE TestPins_TopLevelShorthand2189=== RUN TestPins_ConfigValidation2190=== PAUSE TestPins_ConfigValidation2191=== RUN TestScopes_LegacyProviderDefaultsToWrite2192=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2193=== RUN TestScopes_Rules2194=== PAUSE TestScopes_Rules2195=== RUN TestScopes_ConfigValidation2196=== PAUSE TestScopes_ConfigValidation2197=== CONT TestAudienceForIssuer2198=== CONT TestPins_ConfigValidation2199=== CONT TestValidateToken_KubernetesServiceAccount2200=== CONT TestPins_ReservedForMatchingRule2201--- PASS: TestAudienceForIssuer (0.00s)2202=== CONT TestValidateToken_NoMatchingProvider2203=== CONT TestValidateToken_MultipleProviders2204=== CONT TestValidateToken_BoundSubjectMismatch2205--- PASS: TestPins_ConfigValidation (0.00s)2206=== CONT TestValidateToken_BoundClaimsMismatch2207=== CONT TestValidateToken_Expired2208=== CONT TestValidateToken_WrongAudience2209=== CONT TestValidateToken_ValidToken2210=== CONT TestGlobMatch2211=== RUN TestGlobMatch/foo_foo2212=== PAUSE TestGlobMatch/foo_foo2213=== RUN TestGlobMatch/foo_bar2214=== PAUSE TestGlobMatch/foo_bar2215=== RUN TestGlobMatch/*_2216=== PAUSE TestGlobMatch/*_2217=== RUN TestGlobMatch/*_anything2218=== PAUSE TestGlobMatch/*_anything2219=== RUN TestGlobMatch/foo*_foo2220=== PAUSE TestGlobMatch/foo*_foo2221=== RUN TestGlobMatch/foo*_foobar2222=== PAUSE TestGlobMatch/foo*_foobar2223=== RUN TestGlobMatch/foo*_bar2224=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2225=== CONT TestNewValidator_KubernetesRequiresCA2226=== CONT TestPins_TopLevelShorthand2227=== CONT TestScopes_Rules2228=== CONT TestScopes_ConfigValidation2229=== CONT TestScopes_LegacyProviderDefaultsToWrite2230=== PAUSE TestGlobMatch/foo*_bar2231=== RUN TestGlobMatch/*bar_bar2232=== PAUSE TestGlobMatch/*bar_bar2233=== RUN TestGlobMatch/*bar_foobar2234=== PAUSE TestGlobMatch/*bar_foobar2235=== RUN TestGlobMatch/*bar_foo2236=== PAUSE TestGlobMatch/*bar_foo2237=== RUN TestGlobMatch/foo*bar_foobar2238=== PAUSE TestGlobMatch/foo*bar_foobar2239=== RUN TestGlobMatch/foo*bar_foo123bar2240=== PAUSE TestGlobMatch/foo*bar_foo123bar2241=== RUN TestGlobMatch/foo*bar_foobarbaz2242=== PAUSE TestGlobMatch/foo*bar_foobarbaz2243=== RUN TestGlobMatch/*/*_foo/bar2244=== PAUSE TestGlobMatch/*/*_foo/bar2245=== RUN TestGlobMatch/*/*_foo2246=== PAUSE TestGlobMatch/*/*_foo2247=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2248=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2249=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02250=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02251=== RUN TestGlobMatch/refs/*/main_refs/heads/main2252=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2253=== RUN TestGlobMatch/fo?_foo2254=== PAUSE TestGlobMatch/fo?_foo2255=== RUN TestGlobMatch/fo?_fo2256=== PAUSE TestGlobMatch/fo?_fo2257=== RUN TestGlobMatch/fo?_fooo2258=== PAUSE TestGlobMatch/fo?_fooo2259=== RUN TestGlobMatch/?oo_foo2260=== PAUSE TestGlobMatch/?oo_foo2261=== RUN TestGlobMatch/?oo_boo2262=== PAUSE TestGlobMatch/?oo_boo2263=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2264=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2265=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2266=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2267=== CONT TestGlobMatch/foo_foo2268=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2269=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2270=== CONT TestGlobMatch/?oo_boo2271=== CONT TestGlobMatch/?oo_foo2272=== CONT TestGlobMatch/fo?_fooo2273=== CONT TestGlobMatch/fo?_fo2274=== CONT TestGlobMatch/fo?_foo2275=== CONT TestGlobMatch/refs/*/main_refs/heads/main2276=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02277=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2278=== CONT TestGlobMatch/*/*_foo2279=== CONT TestGlobMatch/*/*_foo/bar2280=== CONT TestGlobMatch/foo*bar_foobarbaz2281=== CONT TestGlobMatch/foo*bar_foo123bar2282=== CONT TestGlobMatch/foo*bar_foobar2283=== CONT TestGlobMatch/*bar_foo2284=== CONT TestGlobMatch/*bar_foobar2285=== CONT TestGlobMatch/*bar_bar2286=== CONT TestGlobMatch/foo*_bar2287=== CONT TestGlobMatch/foo*_foobar2288=== CONT TestGlobMatch/foo*_foo2289=== CONT TestGlobMatch/*_anything2290=== CONT TestGlobMatch/*_2291=== CONT TestGlobMatch/foo_bar2292--- PASS: TestGlobMatch (0.00s)2293 --- PASS: TestGlobMatch/foo_foo (0.00s)2294 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2295 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2296 --- PASS: TestGlobMatch/?oo_boo (0.00s)2297 --- PASS: TestGlobMatch/?oo_foo (0.00s)2298 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2299 --- PASS: TestGlobMatch/fo?_fo (0.00s)2300 --- PASS: TestGlobMatch/fo?_foo (0.00s)2301 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2302 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2303 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2304 --- PASS: TestGlobMatch/*/*_foo (0.00s)2305 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2306 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2307 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2308 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2309 --- PASS: TestGlobMatch/*bar_foo (0.00s)2310 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2311 --- PASS: TestGlobMatch/*bar_bar (0.00s)2312 --- PASS: TestGlobMatch/foo*_bar (0.00s)2313 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2314 --- PASS: TestGlobMatch/foo*_foo (0.00s)2315 --- PASS: TestGlobMatch/*_anything (0.00s)2316 --- PASS: TestGlobMatch/*_ (0.00s)2317 --- PASS: TestGlobMatch/foo_bar (0.00s)2318--- PASS: TestScopes_ConfigValidation (0.00s)23192026/10/14 16:45:17 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:4617723202026/10/14 16:45:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42835/oidc2321--- PASS: TestValidateToken_KubernetesServiceAccount (0.05s)23222026/10/14 16:45:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43483/oidc2323--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.05s)2324--- PASS: TestPins_ReservedForMatchingRule (0.06s)23252026/10/14 16:45:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46659/oidc2326--- PASS: TestValidateToken_BoundClaimsMismatch (0.07s)23272026/10/14 16:45:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35537/oidc2328--- PASS: TestValidateToken_ValidToken (0.08s)23292026/10/14 16:45:17 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:42383/oidc2330--- PASS: TestValidateToken_NoMatchingProvider (0.09s)23312026/10/14 16:45:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41809/oidc23322026/10/14 16:45:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37753/oidc2333--- PASS: TestValidateToken_BoundSubjectMismatch (0.11s)2334--- PASS: TestPins_TopLevelShorthand (0.11s)23352026/10/14 16:45:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41565/oidc2336--- PASS: TestValidateToken_WrongAudience (0.11s)23372026/10/14 16:45:17 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232338--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.13s)23392026/10/14 16:45:18 http: TLS handshake error from 127.0.0.1:46340: remote error: tls: bad certificate2340--- PASS: TestNewValidator_KubernetesRequiresCA (0.24s)23412026/10/14 16:45:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44583/oidc2342--- PASS: TestScopes_Rules (0.27s)23432026/10/14 16:45:18 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38615/oidc2344--- PASS: TestValidateToken_Expired (0.36s)23452026/10/14 16:45:18 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:45519/oidc23462026/10/14 16:45:18 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:45849/oidc2347--- PASS: TestValidateToken_MultipleProviders (0.37s)2348PASS2349Running hook tests...2350=== RUN TestSendPathsEmpty2351=== PAUSE TestSendPathsEmpty2352=== RUN TestQueueEnqueueAndFetch2353=== PAUSE TestQueueEnqueueAndFetch2354=== RUN TestQueueDeduplication2355=== PAUSE TestQueueDeduplication2356=== RUN TestQueueRemove2357=== PAUSE TestQueueRemove2358=== RUN TestQueueFetchBatchLimit2359=== PAUSE TestQueueFetchBatchLimit2360=== RUN TestQueueRetryMovesToBack2361=== PAUSE TestQueueRetryMovesToBack2362=== RUN TestQueueFetchRemoveLifecycle2363=== PAUSE TestQueueFetchRemoveLifecycle2364=== RUN TestQueueConcurrentWriters2365=== PAUSE TestQueueConcurrentWriters2366=== RUN TestQueueRemoveLargeClosure2367=== PAUSE TestQueueRemoveLargeClosure2368=== RUN TestServerClientIntegration2369--- PASS: TestServerClientIntegration (0.00s)2370=== RUN TestServerQueueError23712026/10/14 16:45:18 ERROR Failed to queue paths error="permission denied" count=12372--- PASS: TestServerQueueError (0.00s)2373=== RUN TestGetListenerSocketActivation2374 server_test.go:219: === RUN TestGetListenerSocketActivation2375 --- PASS: TestGetListenerSocketActivation (0.00s)2376 PASS2377 2378--- PASS: TestGetListenerSocketActivation (0.01s)2379=== RUN TestDrainIsolatesPoisonPath2380=== PAUSE TestDrainIsolatesPoisonPath2381=== RUN TestRunNotBlockedByPoisonHead2382=== PAUSE TestRunNotBlockedByPoisonHead2383=== RUN TestDrainGivesUpWhenServerDown2384=== PAUSE TestDrainGivesUpWhenServerDown2385=== RUN TestFailedPathPrunedByLaterClosure2386=== PAUSE TestFailedPathPrunedByLaterClosure2387=== RUN TestWorkerUploadsAndRemoves2388=== PAUSE TestWorkerUploadsAndRemoves2389=== RUN TestWorkerSkipsGCdPaths2390=== PAUSE TestWorkerSkipsGCdPaths2391=== RUN TestWorkerPrunesClosureDeps2392=== PAUSE TestWorkerPrunesClosureDeps2393=== RUN TestDrainTimeout2394=== PAUSE TestDrainTimeout2395=== CONT TestSendPathsEmpty2396--- PASS: TestSendPathsEmpty (0.00s)2397=== CONT TestRunNotBlockedByPoisonHead2398=== CONT TestDrainGivesUpWhenServerDown2399=== CONT TestDrainTimeout2400=== CONT TestQueueFetchRemoveLifecycle2401=== CONT TestWorkerPrunesClosureDeps2402=== CONT TestWorkerSkipsGCdPaths2403=== CONT TestWorkerUploadsAndRemoves2404=== CONT TestQueueRetryMovesToBack2405=== CONT TestFailedPathPrunedByLaterClosure2406=== CONT TestQueueFetchBatchLimit2407=== CONT TestQueueDeduplication2408=== CONT TestQueueEnqueueAndFetch2409=== CONT TestQueueRemove2410=== CONT TestQueueRemoveLargeClosure2411=== CONT TestQueueConcurrentWriters2412=== CONT TestDrainIsolatesPoisonPath24132026/10/14 16:45:18 INFO Upload queue status pending=224142026/10/14 16:45:18 INFO Uploading batch count=124152026/10/14 16:45:18 ERROR Upload failed error="upload failed" count=124162026/10/14 16:45:18 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2943381832/002/nonexistent24172026/10/14 16:45:18 INFO Uploading batch count=424182026/10/14 16:45:18 INFO Uploading batch count=224192026/10/14 16:45:18 ERROR Upload failed error="upload failed" count=424202026/10/14 16:45:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1614952348/002/bbb24212026/10/14 16:45:18 INFO Uploading batch count=124222026/10/14 16:45:18 INFO Uploading batch count=12423--- PASS: TestQueueEnqueueAndFetch (0.01s)24242026/10/14 16:45:18 INFO Upload queue status pending=224252026/10/14 16:45:18 INFO Upload queue status pending=224262026/10/14 16:45:18 INFO Uploading batch count=224272026/10/14 16:45:18 INFO Uploading batch count=12428--- PASS: TestQueueFetchBatchLimit (0.01s)24292026/10/14 16:45:18 INFO Uploading batch count=12430--- PASS: TestQueueFetchRemoveLifecycle (0.01s)24312026/10/14 16:45:18 INFO Upload queue status pending=32432--- PASS: TestQueueRemove (0.01s)24332026/10/14 16:45:18 INFO Uploading batch count=124342026/10/14 16:45:18 ERROR Upload failed error="upload failed" count=124352026/10/14 16:45:18 INFO Uploading batch count=224362026/10/14 16:45:18 ERROR Upload failed error="upload failed" count=224372026/10/14 16:45:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1802081712/002/a24382026/10/14 16:45:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1802081712/002/b24392026/10/14 16:45:18 INFO Uploading batch count=12440--- PASS: TestQueueRetryMovesToBack (0.01s)24412026/10/14 16:45:18 ERROR Upload failed error="upload failed" count=124422026/10/14 16:45:18 INFO Uploading batch count=224432026/10/14 16:45:18 ERROR Upload failed error="upload failed" count=22444--- PASS: TestQueueDeduplication (0.01s)24452026/10/14 16:45:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1802081712/002/c24462026/10/14 16:45:18 INFO Uploading batch count=124472026/10/14 16:45:18 ERROR Upload failed error="upload failed" count=12448--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24492026/10/14 16:45:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1802081712/002/d24502026/10/14 16:45:18 INFO Uploading batch count=124512026/10/14 16:45:18 ERROR Upload failed error="upload failed" count=124522026/10/14 16:45:18 INFO Uploading batch count=224532026/10/14 16:45:18 ERROR Upload failed error="upload failed" count=224542026/10/14 16:45:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1802081712/002/e24552026/10/14 16:45:18 ERROR Drain finished with paths left in queue remaining=124562026/10/14 16:45:18 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1802081712/002/f24572026/10/14 16:45:18 ERROR Drain finished with paths left in queue remaining=102458--- PASS: TestDrainIsolatesPoisonPath (0.02s)2459--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2460--- PASS: TestWorkerUploadsAndRemoves (0.03s)2461--- PASS: TestWorkerSkipsGCdPaths (0.03s)2462--- PASS: TestWorkerPrunesClosureDeps (0.03s)2463--- PASS: TestQueueRemoveLargeClosure (0.09s)2464--- PASS: TestQueueConcurrentWriters (0.20s)24652026/10/14 16:45:18 ERROR Upload failed error="context deadline exceeded" count=224662026/10/14 16:45:18 ERROR Drain finished with paths left in queue remaining=42467--- PASS: TestDrainTimeout (0.21s)24682026/10/14 16:45:19 INFO Uploading batch count=124692026/10/14 16:45:19 INFO Uploading batch count=124702026/10/14 16:45:19 INFO Uploading batch count=124712026/10/14 16:45:19 ERROR Upload failed error="upload failed" count=124722026/10/14 16:45:19 INFO Uploading batch count=124732026/10/14 16:45:19 ERROR Upload failed error="upload failed" count=124742026/10/14 16:45:19 INFO Uploading batch count=124752026/10/14 16:45:19 ERROR Upload failed error="upload failed" count=124762026/10/14 16:45:19 INFO Uploading batch count=124772026/10/14 16:45:19 ERROR Upload failed error="upload failed" count=124782026/10/14 16:45:19 ERROR Drain finished with paths left in queue remaining=12479--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2480PASS2481Running signing tests...2482=== RUN TestExternalSigner2483=== PAUSE TestExternalSigner2484=== RUN TestExternalSignerWrongPublicKey2485=== PAUSE TestExternalSignerWrongPublicKey2486=== RUN TestExternalSignerErrors2487=== PAUSE TestExternalSignerErrors2488=== RUN TestExternalSignerRestartsAfterCrash2489=== PAUSE TestExternalSignerRestartsAfterCrash2490=== RUN TestExternalSignerProgramErrorKeepsProcess2491=== PAUSE TestExternalSignerProgramErrorKeepsProcess2492=== RUN TestExternalSignerClose2493=== PAUSE TestExternalSignerClose2494=== RUN TestExternalSignerRejectsInvalidPublicKey2495=== PAUSE TestExternalSignerRejectsInvalidPublicKey2496=== RUN TestExternalSignerCancellation2497=== PAUSE TestExternalSignerCancellation2498=== RUN TestGenerateFingerprint2499=== PAUSE TestGenerateFingerprint2500=== RUN TestParseSigningKey2501=== PAUSE TestParseSigningKey2502=== RUN TestSign2503=== PAUSE TestSign2504=== RUN TestSignBatch2505=== PAUSE TestSignBatch2506=== RUN TestNilKeyPublicKey2507=== PAUSE TestNilKeyPublicKey2508=== RUN TestSignErrors2509=== PAUSE TestSignErrors2510=== CONT TestExternalSigner2511=== CONT TestExternalSignerCancellation2512=== CONT TestExternalSignerProgramErrorKeepsProcess2513=== CONT TestParseSigningKey2514=== RUN TestParseSigningKey/valid_32-byte_key2515=== CONT TestExternalSignerErrors2516=== PAUSE TestParseSigningKey/valid_32-byte_key2517=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2518=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2519=== RUN TestParseSigningKey/no_colon2520=== PAUSE TestParseSigningKey/no_colon2521=== RUN TestParseSigningKey/empty_name2522=== PAUSE TestParseSigningKey/empty_name2523=== RUN TestParseSigningKey/invalid_base642524=== RUN TestExternalSignerErrors/null2525=== PAUSE TestExternalSignerErrors/null2526=== CONT TestSignBatch2527=== RUN TestExternalSignerErrors/too_few_signatures2528=== PAUSE TestExternalSignerErrors/too_few_signatures2529=== RUN TestExternalSignerErrors/unrequested_key2530=== PAUSE TestExternalSignerErrors/unrequested_key2531=== RUN TestExternalSignerErrors/exit_at_startup2532=== PAUSE TestExternalSignerErrors/exit_at_startup2533=== RUN TestExternalSignerErrors/invalid_signature_base642534=== PAUSE TestExternalSignerErrors/invalid_signature_base642535=== RUN TestExternalSignerErrors/wrong_signature_length2536=== PAUSE TestExternalSignerErrors/wrong_signature_length2537=== RUN TestExternalSignerErrors/program_error2538=== CONT TestSign2539=== CONT TestExternalSignerRejectsInvalidPublicKey2540=== RUN TestExternalSignerRejectsInvalidPublicKey/#002541=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002542=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2543=== CONT TestExternalSignerRestartsAfterCrash2544=== CONT TestExternalSignerClose2545=== CONT TestExternalSignerWrongPublicKey2546=== CONT TestGenerateFingerprint2547=== RUN TestGenerateFingerprint/basic_with_references2548=== PAUSE TestGenerateFingerprint/basic_with_references2549=== RUN TestGenerateFingerprint/no_references2550=== PAUSE TestGenerateFingerprint/no_references2551=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2552=== CONT TestSignErrors2553=== CONT TestNilKeyPublicKey2554--- PASS: TestNilKeyPublicKey (0.00s)2555=== PAUSE TestParseSigningKey/invalid_base642556=== PAUSE TestExternalSignerErrors/program_error2557=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2558=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2559=== RUN TestParseSigningKey/wrong_length2560=== RUN TestExternalSignerErrors/wrong_shape2561=== PAUSE TestExternalSignerErrors/wrong_shape2562=== RUN TestExternalSignerErrors/wrong_id2563=== PAUSE TestExternalSignerErrors/wrong_id2564=== RUN TestExternalSignerErrors/null_signatures2565=== PAUSE TestExternalSignerErrors/null_signatures2566=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2567=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2568=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2569=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2570=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2571=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2572=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2573=== CONT TestExternalSignerRejectsInvalidPublicKey/#002574=== PAUSE TestParseSigningKey/wrong_length2575=== CONT TestParseSigningKey/valid_32-byte_key2576=== RUN TestExternalSignerErrors/wrong_signatures_shape2577=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2578=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2579=== CONT TestParseSigningKey/wrong_length2580=== CONT TestParseSigningKey/invalid_base642581=== CONT TestParseSigningKey/empty_name2582=== CONT TestParseSigningKey/no_colon2583=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2584=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2585=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2586=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2587=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2588--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2589 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2590 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2591 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2592 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2593 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2594=== RUN TestExternalSignerErrors/missing_signature_name2595=== PAUSE TestExternalSignerErrors/missing_signature_name2596=== RUN TestGenerateFingerprint/invalid_nar_hash_length2597=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2598=== RUN TestExternalSignerErrors/wrong_signature_name2599=== PAUSE TestExternalSignerErrors/wrong_signature_name2600=== RUN TestExternalSignerErrors/exit_on_request2601=== RUN TestGenerateFingerprint/invalid_store_path_prefix2602=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2603=== RUN TestGenerateFingerprint/invalid_reference_prefix2604=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2605=== PAUSE TestExternalSignerErrors/exit_on_request2606=== RUN TestExternalSignerErrors/invalid_JSON2607=== PAUSE TestExternalSignerErrors/invalid_JSON2608=== RUN TestExternalSignerErrors/missing_signatures2609=== CONT TestGenerateFingerprint/basic_with_references2610=== RUN TestSignErrors/nil_key2611=== CONT TestGenerateFingerprint/invalid_store_path_prefix2612=== CONT TestGenerateFingerprint/invalid_nar_hash_length2613=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2614=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2615=== CONT TestGenerateFingerprint/invalid_reference_prefix2616=== CONT TestGenerateFingerprint/no_references2617--- PASS: TestSign (0.00s)2618--- PASS: TestParseSigningKey (0.00s)2619 --- PASS: TestParseSigningKey/wrong_length (0.00s)2620 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2621 --- PASS: TestParseSigningKey/empty_name (0.00s)2622 --- PASS: TestParseSigningKey/no_colon (0.00s)2623 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2624 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2625=== PAUSE TestExternalSignerErrors/missing_signatures2626=== PAUSE TestSignErrors/nil_key2627=== CONT TestExternalSignerErrors/missing_signature_name2628=== CONT TestExternalSignerErrors/null_signatures2629=== CONT TestExternalSignerErrors/null2630=== CONT TestExternalSignerErrors/missing_signatures2631=== CONT TestExternalSignerErrors/wrong_shape2632=== CONT TestExternalSignerErrors/program_error2633=== CONT TestExternalSignerErrors/wrong_signature_length2634=== CONT TestExternalSignerErrors/wrong_id2635=== CONT TestExternalSignerErrors/invalid_signature_base642636=== CONT TestExternalSignerErrors/invalid_JSON2637=== CONT TestExternalSignerErrors/exit_at_startup2638=== CONT TestExternalSignerErrors/exit_on_request2639=== CONT TestExternalSignerErrors/unrequested_key2640=== CONT TestExternalSignerErrors/wrong_signature_name2641=== CONT TestExternalSignerErrors/too_few_signatures2642=== CONT TestExternalSignerErrors/wrong_signatures_shape2643=== RUN TestSignErrors/nil_narinfo2644--- PASS: TestGenerateFingerprint (0.00s)2645 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2646 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2647 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2648 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2649 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2650 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2651 --- PASS: TestGenerateFingerprint/no_references (0.00s)2652--- PASS: TestSignBatch (0.00s)2653--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2654=== PAUSE TestSignErrors/nil_narinfo2655=== RUN TestSignErrors/invalid_narinfo2656=== PAUSE TestSignErrors/invalid_narinfo2657=== RUN TestSignErrors/canceled2658=== PAUSE TestSignErrors/canceled2659=== CONT TestSignErrors/nil_key2660=== CONT TestSignErrors/invalid_narinfo2661--- PASS: TestExternalSignerClose (0.01s)2662=== CONT TestSignErrors/canceled2663=== CONT TestSignErrors/nil_narinfo2664--- PASS: TestSignErrors (0.01s)2665 --- PASS: TestSignErrors/nil_key (0.00s)2666 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2667 --- PASS: TestSignErrors/canceled (0.00s)2668 --- PASS: TestSignErrors/nil_narinfo (0.00s)2669--- PASS: TestExternalSignerWrongPublicKey (0.01s)2670--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2671--- PASS: TestExternalSigner (0.01s)2672--- PASS: TestExternalSignerErrors (0.00s)2673 --- PASS: TestExternalSignerErrors/missing_signature_name (0.00s)2674 --- PASS: TestExternalSignerErrors/null_signatures (0.00s)2675 --- PASS: TestExternalSignerErrors/missing_signatures (0.00s)2676 --- PASS: TestExternalSignerErrors/null (0.00s)2677 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2678 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2679 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)2680 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2681 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2682 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)2683 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2684 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2685 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.00s)2686 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2687 --- PASS: TestExternalSignerErrors/program_error (0.01s)2688 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2689--- PASS: TestExternalSignerCancellation (0.02s)2690PASS2691Running OpenBao signer tests...2692=== RUN TestSign2693=== PAUSE TestSign2694=== RUN TestSignErrors2695=== PAUSE TestSignErrors2696=== RUN TestServe2697=== PAUSE TestServe2698=== RUN TestServeRejectsGarbage2699=== PAUSE TestServeRejectsGarbage2700=== CONT TestSign2701=== CONT TestServe2702=== CONT TestServeRejectsGarbage2703=== CONT TestSignErrors2704--- PASS: TestServeRejectsGarbage (0.00s)2705=== RUN TestSignErrors/http_error2706=== PAUSE TestSignErrors/http_error2707=== RUN TestSignErrors/invalid_json2708=== PAUSE TestSignErrors/invalid_json2709=== RUN TestSignErrors/no_prefix2710=== PAUSE TestSignErrors/no_prefix2711=== RUN TestSignErrors/invalid_base642712=== PAUSE TestSignErrors/invalid_base642713=== CONT TestSignErrors/http_error2714=== CONT TestSignErrors/no_prefix2715--- PASS: TestServe (0.00s)2716=== CONT TestSignErrors/invalid_json2717=== CONT TestSignErrors/invalid_base642718--- PASS: TestSign (0.00s)2719--- PASS: TestSignErrors (0.00s)2720 --- PASS: TestSignErrors/no_prefix (0.00s)2721 --- PASS: TestSignErrors/invalid_json (0.00s)2722 --- PASS: TestSignErrors/http_error (0.00s)2723 --- PASS: TestSignErrors/invalid_base64 (0.00s)2724PASS