niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #416
· raw
1tribuchet: building on jamie2Running 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 TestStreamPushRequestLine115=== CONT TestUploadMultipart_SupersededByPeer116=== RUN TestUploadMultipart_SupersededByPeer/exists117=== PAUSE TestUploadMultipart_SupersededByPeer/exists118=== RUN TestUploadMultipart_SupersededByPeer/missing119=== PAUSE TestUploadMultipart_SupersededByPeer/missing120=== CONT TestFileTokenReadsAndCaches121=== CONT TestParsePathInfoJSONMultiplePaths1222026/10/14 16:46:39 ERROR Upload failed error=boom count=1123=== CONT TestScriptTokenCachesUntilRefresh124=== CONT TestScriptTokenNoExpiryRerunsEveryCall125=== CONT TestFileTokenEmpty126=== CONT TestFileTokenMissing127=== CONT TestPathInfoHashCompatibility128=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths129=== CONT TestStreamPushGivesUpOnDeadServer130=== CONT TestStreamPushIsolatesFailures131=== CONT TestScriptTokenEmptyToken132=== CONT TestStreamPushBatchesUnderLoad133=== CONT TestStreamPushReportsEveryPath134=== CONT TestScriptTokenEmptyCommand135=== CONT TestShellSplitErrors136=== CONT TestScriptTokenScriptFails137=== CONT TestShellSplit138=== CONT TestDoWithRetry_FinalResponseBodyReadable139=== CONT TestRetryTimeoutOutlastsMaxRetries140=== CONT TestScriptTokenBadJSON141=== CONT TestDoWithRetry_BodyReplayedViaGetBody142=== CONT TestPathInfoCACompatibility143=== CONT TestRateLimiterFeedback144=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)145=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths146=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths147=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths148--- PASS: TestShellSplitErrors (0.00s)149=== CONT TestResolveStorePath150=== RUN TestRateLimiterFeedback/429_enables_limiter151--- PASS: TestStreamPushReportsEveryPath (0.00s)152=== CONT TestEncodeNixBase32153=== PAUSE TestRateLimiterFeedback/429_enables_limiter154=== CONT TestParsePathInfoJSON155--- PASS: TestScriptTokenEmptyCommand (0.00s)156=== RUN TestParsePathInfoJSON/Nix_format157=== PAUSE TestParsePathInfoJSON/Nix_format158=== RUN TestRateLimiterFeedback/503_enables_limiter159=== RUN TestEncodeNixBase32/test_string_hash160=== PAUSE TestEncodeNixBase32/test_string_hash161=== CONT TestGetStorePathHash162--- PASS: TestFileTokenReadsAndCaches (0.00s)163--- PASS: TestFileTokenMissing (0.00s)164=== RUN TestParsePathInfoJSON/Lix_format165=== PAUSE TestParsePathInfoJSON/Lix_format166=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer167=== RUN TestPathInfoCACompatibility/null_ca_field168=== RUN TestGetStorePathHash/valid_store_path169--- PASS: TestFileTokenEmpty (0.00s)170=== PAUSE TestRateLimiterFeedback/503_enables_limiter171=== PAUSE TestGetStorePathHash/valid_store_path172=== CONT TestConvertHashToNix32173=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess174=== RUN TestEncodeNixBase32/empty_input175=== RUN TestParsePathInfoJSON/empty_input176=== RUN TestGetStorePathHash/basename_without_hyphen_should_error1772026/10/14 16:46:39 WARN Rate limiter enabled after throttle name=server-test rate=5178=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)179=== PAUSE TestEncodeNixBase32/empty_input180=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon181=== CONT TestCaseHackSuffix1822026/10/14 16:46:39 ERROR Upload failed error="connection refused" count=20183=== PAUSE TestPathInfoCACompatibility/null_ca_field1842026/10/14 16:46:39 ERROR Server seems unavailable, giving up on batch untried=17185=== RUN TestPathInfoCACompatibility/old_string_format_-_text186=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text187=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon188=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI189=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI190=== CONT TestUploadMultipart_PartsInParallel1912026/10/14 16:46:39 ERROR Upload failed error="bad path" count=3192=== RUN TestConvertHashToNix32/SRI_format_to_Nix32193=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32194=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter195=== CONT TestEncodeNixBase32WithRealHash196--- PASS: TestScriptTokenScriptFails (0.00s)197=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive198=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512199=== CONT TestFilterOversizedClosures200=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error201=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive202=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error203=== CONT TestPartSizeForNAR204=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica205=== CONT TestRegisterUploadedObjectReusesConnections2062026/10/14 16:46:39 WARN Rate limiter enabled after throttle name=server-test rate=52072026/10/14 16:46:39 WARN Rate limiter enabled after throttle name=server-test rate=5208=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error2092026/10/14 16:46:39 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:39471210=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter211=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter212--- PASS: TestResolveStorePath (0.00s)213=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter2142026/10/14 16:46:39 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:33387215=== RUN TestFilterOversizedClosures/no_limit_keeps_everything2162026/10/14 16:46:39 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:45825217=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything218=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped219=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped220=== RUN TestFilterOversizedClosures/all_closures_skipped2212026/10/14 16:46:39 WARN Rate limiter backed off name=server-test rate=5222=== PAUSE TestFilterOversizedClosures/all_closures_skipped2232026/10/14 16:46:39 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:39471224=== CONT TestDumpPathMatchesNix2252026/10/14 16:46:39 WARN Rate limiter backed off name=server-test rate=52262026/10/14 16:46:39 INFO Garbage collection started227=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry228=== RUN TestPathInfoCACompatibility/new_structured_format_-_text229=== RUN TestConvertHashToNix32/already_Nix32_format230=== RUN TestPartSizeForNAR/zero_stays_at_minimum231=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512232=== CONT TestDumpPathWriterError233=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun234=== PAUSE TestParsePathInfoJSON/empty_input235=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error236--- PASS: TestShellSplit (0.00s)237=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text238=== CONT TestSetClientTLSErrors239=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method240=== CONT TestSetClientTLS241=== RUN TestParsePathInfoJSON/whitespace_only242=== PAUSE TestParsePathInfoJSON/whitespace_only243=== RUN TestParsePathInfoJSON/invalid_JSON244=== PAUSE TestParsePathInfoJSON/invalid_JSON245=== CONT TestStaticToken2462026/10/14 16:46:39 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:45825247=== CONT TestSetClientTLSDoesNotMutateDefaultTransport248=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error249=== CONT TestClientSignaturesByStorePath250=== CONT TestStreamPushReportsSkippedPaths251=== PAUSE TestConvertHashToNix32/already_Nix32_format252=== CONT TestStreamPushStopsWhenCanceled253=== RUN TestConvertHashToNix32/invalid_format254=== PAUSE TestConvertHashToNix32/invalid_format255=== CONT TestUploadMultipart_SupersededByPeer/exists256=== RUN TestSetClientTLSErrors/missing_cert_file257=== PAUSE TestSetClientTLSErrors/missing_cert_file258=== RUN TestSetClientTLSErrors/missing_key_file259=== CONT TestStreamPushReportsSignatures2602026/10/14 16:46:39 INFO Garbage collection started261--- PASS: TestStreamPushIsolatesFailures (0.00s)2622026/10/14 16:46:39 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=0263--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)264--- PASS: TestEncodeNixBase32WithRealHash (0.00s)265--- PASS: TestScriptTokenBadJSON (0.01s)266--- PASS: TestScriptTokenEmptyToken (0.00s)2672026/10/14 16:46:39 ERROR Upload failed error=boom count=1268--- PASS: TestDoServerRequestAttachesToken (0.04s)269=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method270=== CONT TestDumpPathSingleFile271=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths272=== RUN TestSetClientTLS/rejects_connection_without_client_cert273=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert274=== CONT TestEncodeNixBase32/test_string_hash275=== CONT TestEncodeNixBase32/empty_input2762026/10/14 16:46:39 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:45825277=== CONT TestRateLimiterFeedback/429_enables_limiter278=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA279=== CONT TestFilterOversizedClosures/no_limit_keeps_everything280=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter281=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum282--- PASS: TestStreamPushReportsSignatures (0.00s)283--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.04s)284=== PAUSE TestSetClientTLSErrors/missing_key_file285=== CONT TestSupersededNARStillUploadsListing286=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths287=== RUN TestSupersededNARStillUploadsListing/small_NAR288=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA289=== RUN TestSetClientTLSErrors/missing_ca_file290=== CONT TestUploadMultipart_SupersededByPeer/missing291--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.04s)292--- PASS: TestStaticToken (0.00s)293--- PASS: TestClientSignaturesByStorePath (0.00s)294--- PASS: TestStreamPushReportsSkippedPaths (0.00s)295--- PASS: TestStreamPushStopsWhenCanceled (0.00s)296--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)297--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)298--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)299=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter300=== RUN TestPartSizeForNAR/small_stays_at_minimum301=== PAUSE TestPartSizeForNAR/small_stays_at_minimum302=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum303=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum304=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts305=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts306=== RUN TestPartSizeForNAR/1_TiB307=== PAUSE TestPartSizeForNAR/1_TiB308=== RUN TestPartSizeForNAR/5_TiB_S3_max_object309=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object310=== RUN TestPartSizeForNAR/capped_at_5_GiB311=== PAUSE TestPartSizeForNAR/capped_at_5_GiB312=== RUN TestSetClientTLS/preserves_debug_logging_transport313=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3142026/10/14 16:46:39 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=2000315=== PAUSE TestSetClientTLS/preserves_debug_logging_transport316=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)317=== PAUSE TestSupersededNARStillUploadsListing/small_NAR318=== RUN TestSupersededNARStillUploadsListing/dump_cut_short319=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short320=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails3212026/10/14 16:46:39 WARN Garbage collection finished on another replica. Its statistics are not available here322=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails3232026/10/14 16:46:39 WARN Rate limiter enabled after throttle name=s3-test rate=5324=== CONT TestParsePathInfoJSON/Nix_format3252026/10/14 16:46:39 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:350553262026/10/14 16:46:39 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:45825327=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha5123282026/10/14 16:46:39 WARN Rate limiter enabled after throttle name=server-test rate=5329=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error3302026/10/14 16:46:39 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:43281331=== CONT TestParsePathInfoJSON/whitespace_only332--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)333=== CONT TestParsePathInfoJSON/empty_input334=== CONT TestParsePathInfoJSON/Lix_format335=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI3362026/10/14 16:46:39 WARN Rate limiter backed off name=server-test rate=5337=== PAUSE TestSetClientTLSErrors/missing_ca_file338=== RUN TestSetClientTLSErrors/invalid_ca_file339=== CONT TestGetStorePathHash/valid_store_path340=== CONT TestRateLimiterFeedback/503_enables_limiter341=== CONT TestFilterOversizedClosures/all_closures_skipped342=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error343=== CONT TestGetStorePathHash/basename_without_hyphen_should_error344=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive3452026/10/14 16:46:39 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50346=== CONT TestPartSizeForNAR/zero_stays_at_minimum3472026/10/14 16:46:39 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:45825348=== CONT TestPartSizeForNAR/1_TiB3492026/10/14 16:46:39 WARN Rate limiter enabled after throttle name=server-test rate=5350=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum3512026/10/14 16:46:39 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:35231352=== CONT TestConvertHashToNix32/SRI_format_to_Nix32353=== CONT TestConvertHashToNix32/invalid_format354=== CONT TestConvertHashToNix32/already_Nix32_format355--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)3562026/10/14 16:46:39 WARN Rate limiter backed off name=server-test rate=5357=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon358=== CONT TestParsePathInfoJSON/invalid_JSON359=== CONT TestPathInfoCACompatibility/null_ca_field360=== CONT TestPathInfoCACompatibility/new_structured_format_-_text361=== PAUSE TestSetClientTLSErrors/invalid_ca_file362=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method363=== CONT TestPathInfoCACompatibility/old_string_format_-_text364=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails365=== CONT TestSetClientTLSErrors/missing_ca_file366=== CONT TestPartSizeForNAR/small_stays_at_minimum367=== CONT TestSetClientTLSErrors/missing_key_file3682026/10/14 16:46:39 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:45825369=== CONT TestPartSizeForNAR/capped_at_5_GiB3702026/10/14 16:46:39 INFO Uploading abc-hello (1.0GB)371=== CONT TestPartSizeForNAR/5_TiB_S3_max_object372=== CONT TestSetClientTLS/rejects_connection_without_client_cert373--- PASS: TestEncodeNixBase32 (0.01s)374 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)375 --- PASS: TestEncodeNixBase32/empty_input (0.00s)376--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)377 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)378 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)379--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)380 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)381 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)382=== CONT TestSetClientTLS/preserves_debug_logging_transport383=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA384=== CONT TestSupersededNARStillUploadsListing/small_NAR385=== CONT TestSupersededNARStillUploadsListing/dump_cut_short386=== CONT TestSetClientTLSErrors/missing_cert_file387=== CONT TestSetClientTLSErrors/invalid_ca_file388=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts389--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s)390--- PASS: TestFilterOversizedClosures (0.03s)391 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)392 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)393 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)394--- PASS: TestConvertHashToNix32 (0.03s)395 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)396 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)397 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)398--- PASS: TestGetStorePathHash (0.04s)399 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)400 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)401 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)402 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)403--- PASS: TestPathInfoCACompatibility (0.04s)404 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)405 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)406 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)407 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)408 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)409--- PASS: TestRateLimiterFeedback (0.04s)410 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)411 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)412 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)413 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)4142026/10/14 16:46:40 INFO Uploading abc-hello (1.0GB)415--- PASS: TestParsePathInfoJSON (0.04s)416 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)417 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)418 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)419 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)420 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)421--- PASS: TestPathInfoHashCompatibility (0.04s)422 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)423 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)424 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)425 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)426--- PASS: TestPartSizeForNAR (0.02s)427 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)428 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)429 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)430 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)431 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)432 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)433 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)434--- PASS: TestSetClientTLSErrors (0.02s)435 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)436 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)437 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)438 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)4392026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:458254402026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:45825441--- PASS: TestCaseHackSuffix (0.18s)442--- PASS: TestStreamPushRequestLine (0.19s)4432026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:45825444--- PASS: TestStreamPushBatchesUnderLoad (0.19s)445--- PASS: TestDumpPathSingleFile (0.15s)4462026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:458254472026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:458254482026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:458254492026/10/14 16:46:40 http: TLS handshake error from 127.0.0.1:53834: remote error: tls: bad certificate4502026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:45825451--- PASS: TestSetClientTLS (0.02s)452 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.13s)453 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.13s)454 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.14s)4552026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:458254562026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:458254572026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:458254582026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:45825459--- PASS: TestRegisterUploadedObjectReusesConnections (0.17s)4602026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:458254612026/10/14 16:46:40 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:45825462--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.21s)463--- PASS: TestDumpPathWriterError (0.18s)4642026/10/14 16:46:40 INFO Uploading abc-hello (1.0GB)465--- PASS: TestDumpPathMatchesNix (0.23s)4662026/10/14 16:46:40 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:43755/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:43755/part/24672026/10/14 16:46:40 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"468--- PASS: TestSupersededNARStillUploadsListing (0.00s)469 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.14s)470 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.14s)471 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.70s)472--- PASS: TestUploadMultipart_PartsInParallel (0.76s)4732026/10/14 16:46:40 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:34587/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:34587/api/uploads/complete4742026/10/14 16:46:40 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4752026/10/14 16:46:40 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:34587/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:34587/api/uploads/complete476--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4772026/10/14 16:46:40 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4782026/10/14 16:46:40 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:34587/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:34587/api/uploads/complete4792026/10/14 16:46:40 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"480--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)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/postgres1358598781/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/postgres1358598781/data -l logfile start509510/build/postgres1358598781:5432 - no response5112026-10-14 16:46:41.751 UTC [128] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit5122026-10-14 16:46:41.752 UTC [128] LOG: listening on Unix socket "/build/postgres1358598781/.s.PGSQL.5432"5132026-10-14 16:46:41.757 UTC [135] LOG: database system was shut down at 2026-10-14 16:46:41 UTC5142026-10-14 16:46:41.760 UTC [128] LOG: database system is ready to accept connections515/build/postgres1358598781:5432 - accepting connections516{"timestamp":"2026-10-14T16:46:42.054295198Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"e978aab5-c4d0-455f-9b86-b154e0fccb54","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(393)"}517=== RUN TestService_AuthMiddleware518=== PAUSE TestService_AuthMiddleware519=== RUN TestService_AuthMiddleware_MTLSProxyHeader520=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader521=== RUN TestService_AuthMiddleware_MTLSBoundSubjects522=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects523=== RUN TestService_ReadAuthMiddleware524=== PAUSE TestService_ReadAuthMiddleware525=== RUN TestService_AuthMiddleware_OIDC526=== PAUSE TestService_AuthMiddleware_OIDC527=== RUN TestService_RequireScope_OIDC528=== PAUSE TestService_RequireScope_OIDC529=== RUN TestService_ReadScope_PublicByDefault530=== PAUSE TestService_ReadScope_PublicByDefault531=== RUN TestCacheConfigHandler532=== PAUSE TestCacheConfigHandler533=== RUN TestCacheStatsHandler534=== PAUSE TestCacheStatsHandler535=== RUN TestClientCADerivations536=== PAUSE TestClientCADerivations537=== RUN TestClientErrorHandling538=== PAUSE TestClientErrorHandling539=== RUN TestClientIntegration540=== PAUSE TestClientIntegration541=== RUN TestClientMultipleUploads542=== PAUSE TestClientMultipleUploads543=== RUN TestClientWithDependencies544=== PAUSE TestClientWithDependencies545=== RUN TestClientSharedPathCommittedMidPush546=== PAUSE TestClientSharedPathCommittedMidPush547=== RUN TestPinProtectsFromGC548=== PAUSE TestPinProtectsFromGC549=== RUN TestClientPushesUseOnePush550=== PAUSE TestClientPushesUseOnePush551=== RUN TestClientFallsBackToClosures552=== PAUSE TestClientFallsBackToClosures553=== RUN TestDeleteClosuresRacingPins554=== PAUSE TestDeleteClosuresRacingPins555=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock556=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock557=== RUN TestResolveDBConnectionString558=== PAUSE TestResolveDBConnectionString559=== RUN TestConnectWaitsForAPeerMigration560=== PAUSE TestConnectWaitsForAPeerMigration561=== RUN TestLeadElectsOneAndHandsOver562=== PAUSE TestLeadElectsOneAndHandsOver563=== RUN TestLeadIncumbentWinsAfterRestart5642026/10/14 16:46:42 INFO lead: acquired remote=192.0.2.1:12345652026/10/14 16:46:42 INFO lead: released remote=192.0.2.1:12345662026/10/14 16:46:42 INFO lead: acquired remote=192.0.2.1:12345672026/10/14 16:46:44 INFO lead: released remote=192.0.2.1:1234568--- PASS: TestLeadIncumbentWinsAfterRestart (1.89s)569=== RUN TestLeadIncumbentAnnouncesAtOnce570=== PAUSE TestLeadIncumbentAnnouncesAtOnce571=== RUN TestLeadEndsOnShutdown572=== PAUSE TestLeadEndsOnShutdown573=== RUN TestLeadEndsWhenItsConnectionHangs5742026/10/14 16:46:44 INFO lead: acquired remote=192.0.2.1:12345752026-10-14 16:46:45.567 UTC [577] FATAL: terminating connection due to administrator command5762026/10/14 16:46:45 INFO lead: acquired remote=192.0.2.1:12345772026/10/14 16:46:46 WARN lead: lock connection lost error="timeout: context deadline exceeded"5782026/10/14 16:46:46 INFO lead: released remote=192.0.2.1:12345792026/10/14 16:46:46 INFO lead: released remote=192.0.2.1:1234580--- PASS: TestLeadEndsWhenItsConnectionHangs (2.91s)581=== RUN TestGCAdvisoryLockBlocksConcurrentRun582=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun583=== RUN TestGCBugBareHashReferences584=== PAUSE TestGCBugBareHashReferences585=== RUN TestGCMetrics586=== PAUSE TestGCMetrics587=== RUN TestPushDedupSurvivesConcurrentGC588=== PAUSE TestPushDedupSurvivesConcurrentGC589=== RUN TestDeduplicatedObjectsRecordedAsPending590=== PAUSE TestDeduplicatedObjectsRecordedAsPending591=== RUN TestGCSweepSkipsPendingObjects592=== PAUSE TestGCSweepSkipsPendingObjects593=== RUN TestTombstonedObjectOfferedWithoutWaiting594=== PAUSE TestTombstonedObjectOfferedWithoutWaiting595=== RUN TestGCSweepDeliversEachKeyOnce596=== PAUSE TestGCSweepDeliversEachKeyOnce597=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection598=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection599=== RUN TestForceGCDuringPushOffersSweptObject600=== PAUSE TestForceGCDuringPushOffersSweptObject601=== RUN TestFailedS3DeleteKeepsTombstone602=== PAUSE TestFailedS3DeleteKeepsTombstone603=== RUN TestSweepSkipsRowsLockedByPush604=== PAUSE TestSweepSkipsRowsLockedByPush605=== RUN TestRegisterCompletedObjectNeedsPendingRow606=== PAUSE TestRegisterCompletedObjectNeedsPendingRow607=== RUN TestGetExistingObjectsLocksRows608=== PAUSE TestGetExistingObjectsLocksRows609=== RUN TestSweepRechecksPendingAfterLocking610=== PAUSE TestSweepRechecksPendingAfterLocking611=== RUN TestPushWaitsForSweepHoldingRow612=== PAUSE TestPushWaitsForSweepHoldingRow613=== RUN TestCommitRacingPendingCleanupKeepsObjects614=== PAUSE TestCommitRacingPendingCleanupKeepsObjects615=== RUN TestGCEndsOnShutdown616=== PAUSE TestGCEndsOnShutdown617=== RUN TestGCTaskStore_StartNew618=== PAUSE TestGCTaskStore_StartNew619=== RUN TestGCTaskStore_DeduplicateSameParams620=== PAUSE TestGCTaskStore_DeduplicateSameParams621=== RUN TestGCTaskStore_ConflictDifferentParams622=== PAUSE TestGCTaskStore_ConflictDifferentParams623=== RUN TestGCTaskStore_GetEmpty624=== PAUSE TestGCTaskStore_GetEmpty625=== RUN TestGCTaskStore_GetReturnsLatest626=== PAUSE TestGCTaskStore_GetReturnsLatest627=== RUN TestGCTaskStore_CompletedAllowsNewTask628=== PAUSE TestGCTaskStore_CompletedAllowsNewTask629=== RUN TestGCTaskStore_PhaseUpdates630=== PAUSE TestGCTaskStore_PhaseUpdates631=== RUN TestGCTaskStore_Fail632=== PAUSE TestGCTaskStore_Fail633=== RUN TestGracefulShutdownDrainsInflight634=== PAUSE TestGracefulShutdownDrainsInflight635=== RUN TestService_healthCheckHandler636=== PAUSE TestService_healthCheckHandler637=== RUN TestService_readinessHandler638=== PAUSE TestService_readinessHandler639=== RUN TestGenerateLandingPage640=== PAUSE TestGenerateLandingPage641=== RUN TestCacheConfigHandlerMaxNarSize642=== PAUSE TestCacheConfigHandlerMaxNarSize643=== RUN TestCreatePendingClosureRejectsOversizedNAR644=== PAUSE TestCreatePendingClosureRejectsOversizedNAR645=== RUN TestNARDeduplicationMetadataUploadBug646=== PAUSE TestNARDeduplicationMetadataUploadBug647=== RUN TestMetricsInventory648=== PAUSE TestMetricsInventory649=== RUN TestMetricsCommit650=== PAUSE TestMetricsCommit651=== RUN TestService_NativeMTLS652=== PAUSE TestService_NativeMTLS653=== RUN TestServerTLSConfig654=== PAUSE TestServerTLSConfig655=== RUN TestMultipartCleanup656=== PAUSE TestMultipartCleanup657=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded658=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded659=== RUN TestPendingCleanupUsesOneCutoff660=== PAUSE TestPendingCleanupUsesOneCutoff661=== RUN TestObjectStatsTrigger662=== PAUSE TestObjectStatsTrigger663=== RUN TestObjectStatsLargeCommit664=== PAUSE TestObjectStatsLargeCommit665=== RUN TestOrphanedObjectsGC666=== PAUSE TestOrphanedObjectsGC667=== RUN TestOrphanedObjectsGCStressTest668=== PAUSE TestOrphanedObjectsGCStressTest669=== RUN TestCreatePin_ReservedPins670=== PAUSE TestCreatePin_ReservedPins671=== RUN TestPresentReportsOnlyClosureRoots672=== PAUSE TestPresentReportsOnlyClosureRoots673=== RUN TestPresentRefreshesOnlyStaleClosures674=== PAUSE TestPresentRefreshesOnlyStaleClosures675=== RUN TestPresentNotReportedWhileGCDeletesClosure676=== PAUSE TestPresentNotReportedWhileGCDeletesClosure677=== RUN TestParseSingleRange678=== PAUSE TestParseSingleRange679=== RUN TestProxyHeadersOnlyTrustedOnSocket6802026/10/14 16:46:47 INFO Starting HTTP server address=proxy.sock6812026/10/14 16:46:47 INFO Starting HTTP server address=127.0.0.1:355436822026/10/14 16:46:47 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6832026/10/14 16:46:47 INFO Shutdown signal received, draining in-flight requests timeout=10s684--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.12s)685=== RUN TestIsValidCachePath686=== PAUSE TestIsValidCachePath687=== RUN TestReadProxyNarinfo688=== PAUSE TestReadProxyNarinfo689=== RUN TestReadProxyNarinfoAlreadyDecompressed690=== PAUSE TestReadProxyNarinfoAlreadyDecompressed691=== RUN TestReadProxyContentNegotiation692=== PAUSE TestReadProxyContentNegotiation693=== RUN TestReadProxyNarStreaming694=== PAUSE TestReadProxyNarStreaming695=== RUN TestReadProxy404696=== PAUSE TestReadProxy404697=== RUN TestReadProxyInvalidPath698=== PAUSE TestReadProxyInvalidPath699=== RUN TestReadProxyHead700=== PAUSE TestReadProxyHead701=== RUN TestReadProxyOutlastsServerWriteTimeout702=== PAUSE TestReadProxyOutlastsServerWriteTimeout703=== RUN TestReadProxyConditionalGet704=== PAUSE TestReadProxyConditionalGet705=== RUN TestReadProxyRootRedirectsToIndexHTML706=== PAUSE TestReadProxyRootRedirectsToIndexHTML707=== RUN TestReadProxyDisabled708=== PAUSE TestReadProxyDisabled709=== RUN TestReadRedirectNar710=== PAUSE TestReadRedirectNar711=== RUN TestReadRedirectKeepsNarinfoProxied712=== PAUSE TestReadRedirectKeepsNarinfoProxied713=== RUN TestReadProxyRangeRequest714=== PAUSE TestReadProxyRangeRequest715=== RUN TestReadRedirectUsesPublicS3URL716=== PAUSE TestReadRedirectUsesPublicS3URL717=== RUN TestPush_OverlappingRootsStoreOneRowPerKey718=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey719=== RUN TestPush_CompleteCommitsEveryRoot720=== PAUSE TestPush_CompleteCommitsEveryRoot721=== RUN TestPush_RepeatedRootCommitsOnce722=== PAUSE TestPush_RepeatedRootCommitsOnce723=== RUN TestPush_CompleteWaitsForCleanupOfThePush724=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush725=== RUN TestPush_RootsAreLockedInByteOrder726=== PAUSE TestPush_RootsAreLockedInByteOrder727=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit728=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit729=== RUN TestPush_RejectsBadRequests730=== PAUSE TestPush_RejectsBadRequests731=== RUN TestPush_SignsNarinfosOfItsPendingObjects732=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects733=== RUN TestRedundantMultipartUpload734=== PAUSE TestRedundantMultipartUpload735=== RUN TestCompleteMultipartUpload_ErrorButObjectExists736=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists737=== RUN TestCompletedNarNotReofferedAcrossClosures738=== PAUSE TestCompletedNarNotReofferedAcrossClosures739=== RUN TestPresignedUploadRegisteredBeforeCommit740=== PAUSE TestPresignedUploadRegisteredBeforeCommit741=== RUN TestService_Rustfstest742=== PAUSE TestService_Rustfstest743=== RUN TestParseSize744=== PAUSE TestParseSize745=== RUN TestSkippedUploadsHandler746=== PAUSE TestSkippedUploadsHandler747=== RUN TestSystemdListenerNotActivated748--- PASS: TestSystemdListenerNotActivated (0.00s)749=== RUN TestWatchdogBeatsWhenHealthy750--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)751=== RUN TestWatchdogSkipsWhenUnhealthy7522026/10/14 16:46:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7532026/10/14 16:46:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7542026/10/14 16:46:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7552026/10/14 16:46:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7562026/10/14 16:46:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7572026/10/14 16:46:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/14 16:46:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/14 16:46:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/14 16:46:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/14 16:46:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"762--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)763=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle764=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle765=== RUN TestProxyWriteTimeout766=== PAUSE TestProxyWriteTimeout767=== RUN TestPendingClosureWriteTimeout768=== PAUSE TestPendingClosureWriteTimeout769=== RUN TestIsValidUploadKey770=== PAUSE TestIsValidUploadKey771=== RUN TestUploadHandlersRejectInvalidKeys772=== PAUSE TestUploadHandlersRejectInvalidKeys773=== RUN TestUploadHandlersRejectOversizedBody774=== PAUSE TestUploadHandlersRejectOversizedBody775=== RUN TestService_cleanupPendingClosuresHandler776=== PAUSE TestService_cleanupPendingClosuresHandler777=== RUN TestService_createPendingClosureHandler778=== PAUSE TestService_createPendingClosureHandler779=== RUN TestService_verifyS3Integrity780=== PAUSE TestService_verifyS3Integrity781=== RUN TestCompleteMultipartUnregistered782=== PAUSE TestCompleteMultipartUnregistered783=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT784=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT785=== CONT TestService_AuthMiddleware786=== CONT TestService_verifyS3Integrity787=== CONT TestRegisterCompletedObjectNeedsPendingRow788=== CONT TestPush_RejectsBadRequests789=== CONT TestIsValidCachePath790=== RUN TestIsValidCachePath/narinfo791=== CONT TestPush_RootsAreLockedInByteOrder792=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT793=== CONT TestCompleteMultipartUnregistered794=== CONT TestService_createPendingClosureHandler795=== CONT TestService_cleanupPendingClosuresHandler796=== CONT TestUploadHandlersRejectOversizedBody797=== CONT TestUploadHandlersRejectInvalidKeys798=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info799=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info800=== CONT TestIsValidUploadKey801=== CONT TestPendingClosureWriteTimeout802=== CONT TestProxyWriteTimeout803=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle804=== CONT TestSkippedUploadsHandler805=== CONT TestParseSize806=== CONT TestService_Rustfstest807=== CONT TestPresignedUploadRegisteredBeforeCommit808=== CONT TestCompletedNarNotReofferedAcrossClosures809=== CONT TestCompleteMultipartUpload_ErrorButObjectExists810=== CONT TestRedundantMultipartUpload811=== CONT TestPush_SignsNarinfosOfItsPendingObjects812=== PAUSE TestIsValidCachePath/narinfo813=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal814=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal815=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key816=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key817=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key818=== RUN TestProxyWriteTimeout/narinfo819--- PASS: TestParseSize (0.00s)820=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock821=== RUN TestIsValidUploadKey/narinfo822=== PAUSE TestIsValidUploadKey/narinfo823=== RUN TestIsValidUploadKey/nar_zst824=== RUN TestPendingClosureWriteTimeout/empty8252026/10/14 16:46:47 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000826=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars827=== PAUSE TestIsValidUploadKey/nar_zst828=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars829=== PAUSE TestPendingClosureWriteTimeout/empty830=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key831=== PAUSE TestProxyWriteTimeout/narinfo832=== RUN TestProxyWriteTimeout/1_GiB_nar833=== RUN TestIsValidUploadKey/nar_xz834=== PAUSE TestIsValidUploadKey/nar_xz835=== RUN TestIsValidCachePath/nar_zst836=== PAUSE TestIsValidCachePath/nar_zst837=== RUN TestIsValidCachePath/nar_xz838=== PAUSE TestIsValidCachePath/nar_xz839=== RUN TestPendingClosureWriteTimeout/400_objects840=== PAUSE TestPendingClosureWriteTimeout/400_objects841=== CONT TestSweepSkipsRowsLockedByPush842=== PAUSE TestProxyWriteTimeout/1_GiB_nar843=== RUN TestProxyWriteTimeout/10_GiB_nar844=== PAUSE TestProxyWriteTimeout/10_GiB_nar845=== RUN TestProxyWriteTimeout/unknown_size846=== PAUSE TestProxyWriteTimeout/unknown_size847=== RUN TestIsValidUploadKey/nar_plain848=== PAUSE TestIsValidUploadKey/nar_plain849=== RUN TestIsValidUploadKey/listing850=== PAUSE TestIsValidUploadKey/listing851=== RUN TestIsValidUploadKey/build_log852=== RUN TestIsValidCachePath/nar_bz2853=== RUN TestPendingClosureWriteTimeout/670k_objects854=== PAUSE TestPendingClosureWriteTimeout/670k_objects855=== CONT TestFailedS3DeleteKeepsTombstone856=== PAUSE TestIsValidUploadKey/build_log857=== RUN TestIsValidUploadKey/build_log_home-manager_file858=== PAUSE TestIsValidCachePath/nar_bz2859=== RUN TestIsValidCachePath/nar_uncompressed860=== PAUSE TestIsValidCachePath/nar_uncompressed861=== RUN TestIsValidCachePath/ls862=== PAUSE TestIsValidCachePath/ls863=== RUN TestIsValidCachePath/log864=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline865=== PAUSE TestIsValidUploadKey/build_log_home-manager_file866=== RUN TestIsValidUploadKey/build_log_plus_in_name867=== PAUSE TestIsValidUploadKey/build_log_plus_in_name868=== PAUSE TestIsValidCachePath/log869=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline870=== RUN TestIsValidUploadKey/build_log_question_mark871=== RUN TestIsValidCachePath/realisation872=== PAUSE TestIsValidCachePath/realisation873=== CONT TestForceGCDuringPushOffersSweptObject874=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows875=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows876=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check877=== PAUSE TestIsValidUploadKey/build_log_question_mark878=== RUN TestIsValidUploadKey/build_log_equals879=== PAUSE TestIsValidUploadKey/build_log_equals880=== RUN TestIsValidUploadKey/realisation881=== RUN TestIsValidCachePath/nix-cache-info882=== PAUSE TestIsValidCachePath/nix-cache-info883=== RUN TestIsValidCachePath/index.html884=== PAUSE TestIsValidCachePath/index.html885=== RUN TestIsValidCachePath/traversal_parent886=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check887--- PASS: TestSkippedUploadsHandler (0.09s)888=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection889=== PAUSE TestIsValidUploadKey/realisation890=== PAUSE TestIsValidCachePath/traversal_parent891=== CONT TestGCSweepDeliversEachKeyOnce892=== RUN TestIsValidUploadKey/realisation_plus_in_output893=== PAUSE TestIsValidUploadKey/realisation_plus_in_output894=== RUN TestIsValidUploadKey/nix-cache-info895=== PAUSE TestIsValidUploadKey/nix-cache-info896=== RUN TestIsValidUploadKey/index.html897=== PAUSE TestIsValidUploadKey/index.html898=== RUN TestIsValidUploadKey/narinfo_key,_nar_type899=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type900=== RUN TestIsValidCachePath/traversal_in_middle901=== PAUSE TestIsValidCachePath/traversal_in_middle902=== RUN TestIsValidUploadKey/nar_key,_narinfo_type903=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type904=== RUN TestIsValidCachePath/invalid_char_e905=== PAUSE TestIsValidCachePath/invalid_char_e906=== RUN TestIsValidUploadKey/listing_key,_narinfo_type907=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type908=== RUN TestIsValidCachePath/invalid_char_u909=== PAUSE TestIsValidCachePath/invalid_char_u910=== RUN TestIsValidCachePath/random_path911=== PAUSE TestIsValidCachePath/random_path912=== RUN TestIsValidCachePath/empty913=== PAUSE TestIsValidCachePath/empty914=== RUN TestIsValidCachePath/leading_slash915=== PAUSE TestIsValidCachePath/leading_slash916=== RUN TestIsValidCachePath/wrong_extension917=== PAUSE TestIsValidCachePath/wrong_extension918=== RUN TestIsValidCachePath/short_hash919=== PAUSE TestIsValidCachePath/short_hash920=== RUN TestIsValidUploadKey/traversal921=== PAUSE TestIsValidUploadKey/traversal922=== CONT TestTombstonedObjectOfferedWithoutWaiting923=== RUN TestIsValidUploadKey/traversal_nar924=== PAUSE TestIsValidUploadKey/traversal_nar925=== RUN TestIsValidUploadKey/absolute926=== PAUSE TestIsValidUploadKey/absolute927=== RUN TestIsValidUploadKey/empty_key928=== PAUSE TestIsValidUploadKey/empty_key929=== RUN TestIsValidUploadKey/unknown_type930=== PAUSE TestIsValidUploadKey/unknown_type931=== CONT TestGCSweepSkipsPendingObjects932=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts933=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts934=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure935=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure936=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart937=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart938=== CONT TestDeduplicatedObjectsRecordedAsPending9392026/10/14 16:46:47 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"940--- PASS: TestService_AuthMiddleware (0.30s)941=== CONT TestPushDedupSurvivesConcurrentGC942=== RUN TestPush_RejectsBadRequests/no_roots943=== PAUSE TestPush_RejectsBadRequests/no_roots944=== RUN TestPush_RejectsBadRequests/no_objects945=== PAUSE TestPush_RejectsBadRequests/no_objects946=== RUN TestPush_RejectsBadRequests/bad_root947=== PAUSE TestPush_RejectsBadRequests/bad_root948=== RUN TestPush_RejectsBadRequests/root_not_in_objects949=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects950=== CONT TestGCMetrics9512026/10/14 16:46:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9522026/10/14 16:46:47 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst953--- PASS: TestCompleteMultipartUnregistered (0.35s)954=== CONT TestGCBugBareHashReferences9552026/10/14 16:46:47 INFO Received push request method=POST path=/api/pushes956--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.41s)957=== CONT TestGCAdvisoryLockBlocksConcurrentRun9582026-10-14 16:46:47.739 UTC [689] ERROR: could not obtain lock on row in relation "closures"9592026-10-14 16:46:47.739 UTC [689] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9602026-10-14 16:46:47.740 UTC [689] ERROR: could not obtain lock on row in relation "closures"9612026-10-14 16:46:47.740 UTC [689] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9622026-10-14 16:46:47.740 UTC [689] ERROR: could not obtain lock on row in relation "closures"9632026-10-14 16:46:47.740 UTC [689] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9642026-10-14 16:46:47.740 UTC [689] ERROR: could not obtain lock on row in relation "closures"9652026-10-14 16:46:47.740 UTC [689] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9662026-10-14 16:46:47.741 UTC [689] ERROR: could not obtain lock on row in relation "closures"9672026-10-14 16:46:47.741 UTC [689] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT968--- PASS: TestPush_RootsAreLockedInByteOrder (0.43s)969=== CONT TestLeadEndsOnShutdown9702026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures9712026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures9722026/10/14 16:46:47 INFO Received push request method=POST path=/api/pushes9732026/10/14 16:46:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9742026/10/14 16:46:47 INFO Signed narinfos id=1 count=19752026/10/14 16:46:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9762026/10/14 16:46:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9772026/10/14 16:46:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9782026/10/14 16:46:47 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9792026/10/14 16:46:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9802026/10/14 16:46:47 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9812026/10/14 16:46:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9822026/10/14 16:46:47 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19832026/10/14 16:46:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9842026/10/14 16:46:47 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo985--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.50s)986=== CONT TestLeadIncumbentAnnouncesAtOnce9872026/10/14 16:46:47 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZjM2ODBiNzYtMGZiOS00OGRmLTk2NmQtMmFmNjI2OTMzNzdiLmZkYTdiMmExLTMyZjEtNDEzZS05YzFlLWYyNWU5MzhmMGI2MHgxNzkxOTk2NDA3Nzk0NzY0MTE09882026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures9892026/10/14 16:46:47 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZjM2ODBiNzYtMGZiOS00OGRmLTk2NmQtMmFmNjI2OTMzNzdiLmZkYTdiMmExLTMyZjEtNDEzZS05YzFlLWYyNWU5MzhmMGI2MHgxNzkxOTk2NDA3Nzk0NzY0MTE0 parts=1990--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.50s)991=== CONT TestLeadElectsOneAndHandsOver992--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.53s)993=== CONT TestConnectWaitsForAPeerMigration9942026/10/14 16:46:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9952026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures9962026/10/14 16:46:47 INFO Received cleanup request method=DELETE path=/api/pending_closures9972026/10/14 16:46:47 INFO Aborted multipart uploads count=0 kept=09982026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures9992026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures10002026/10/14 16:46:47 INFO Received cleanup request method=DELETE path=/api/pending_closures10012026/10/14 16:46:47 INFO Aborted multipart uploads count=1 kept=010022026/10/14 16:46:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10032026-10-14 16:46:47.931 UTC [661] ERROR: Closure does not exist: id=110042026-10-14 16:46:47.931 UTC [661] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10052026-10-14 16:46:47.931 UTC [661] STATEMENT: -- name: CommitPendingClosure :one1006 SELECT commit_pending_closure($1::bigint)::bigint1007 1008--- PASS: TestService_cleanupPendingClosuresHandler (0.61s)1009=== CONT TestResolveDBConnectionString1010=== RUN TestResolveDBConnectionString/flag_wins1011=== PAUSE TestResolveDBConnectionString/flag_wins1012=== RUN TestResolveDBConnectionString/file_when_flag_empty1013=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1014=== RUN TestResolveDBConnectionString/missing_file_is_an_error1015=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1016=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1017=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1018=== RUN TestResolveDBConnectionString/nothing_configured1019=== PAUSE TestResolveDBConnectionString/nothing_configured1020=== CONT TestReadProxyRootRedirectsToIndexHTML10212026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures10222026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures10232026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures10242026/10/14 16:46:47 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10252026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures1026--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.62s)1027=== CONT TestPush_CompleteWaitsForCleanupOfThePush10282026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures10292026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures10302026/10/14 16:46:47 INFO Received uploads request method=POST path=/api/pending_closures10312026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures1032--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.56s)1033=== CONT TestPush_RepeatedRootCommitsOnce10342026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures10352026/10/14 16:46:48 INFO Aborted multipart uploads count=0 kept=010362026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures10372026/10/14 16:46:48 WARN Force mode enabled - objects will be deleted immediately without grace period10382026/10/14 16:46:48 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."10392026/10/14 16:46:48 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1040--- PASS: TestFailedS3DeleteKeepsTombstone (0.69s)1041=== CONT TestPush_CompleteCommitsEveryRoot1042--- PASS: TestService_Rustfstest (0.78s)1043=== CONT TestPush_OverlappingRootsStoreOneRowPerKey10442026/10/14 16:46:48 INFO Aborted multipart uploads count=0 kept=010452026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures10462026/10/14 16:46:48 WARN Force mode enabled - objects will be deleted immediately without grace period10472026/10/14 16:46:48 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=010482026/10/14 16:46:48 INFO Vacuumed table table=pending_closures1049--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.79s)1050=== CONT TestReadRedirectUsesPublicS3URL10512026/10/14 16:46:48 INFO Vacuumed table table=pending_objects10522026/10/14 16:46:48 INFO Vacuumed table table=multipart_uploads10532026/10/14 16:46:48 INFO Vacuumed table table=closures10542026/10/14 16:46:48 INFO Vacuumed table table=objects10552026/10/14 16:46:48 INFO Aborted multipart uploads count=0 kept=010562026/10/14 16:46:48 WARN Force mode enabled - objects will be deleted immediately without grace period10572026/10/14 16:46:48 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=010582026/10/14 16:46:48 INFO Vacuumed table table=pending_closures10592026/10/14 16:46:48 INFO Vacuumed table table=pending_objects10602026/10/14 16:46:48 INFO Vacuumed table table=multipart_uploads10612026/10/14 16:46:48 INFO Vacuumed table table=closures10622026/10/14 16:46:48 INFO Vacuumed table table=objects1063--- PASS: TestSweepSkipsRowsLockedByPush (0.82s)1064=== CONT TestReadProxyRangeRequest10652026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures10662026/10/14 16:46:48 INFO Aborted multipart uploads count=0 kept=010672026/10/14 16:46:48 WARN Force mode enabled - objects will be deleted immediately without grace period10682026/10/14 16:46:48 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=010692026/10/14 16:46:48 INFO Aborted multipart uploads count=0 kept=010702026/10/14 16:46:48 INFO Vacuumed table table=pending_closures10712026/10/14 16:46:48 INFO Vacuumed table table=pending_objects10722026/10/14 16:46:48 INFO Vacuumed table table=multipart_uploads10732026/10/14 16:46:48 INFO Vacuumed table table=closures10742026/10/14 16:46:48 WARN Force mode enabled - objects will be deleted immediately without grace period10752026/10/14 16:46:48 INFO Vacuumed table table=objects1076--- PASS: TestGCSweepDeliversEachKeyOnce (0.86s)1077=== CONT TestReadRedirectKeepsNarinfoProxied10782026/10/14 16:46:48 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=010792026/10/14 16:46:48 INFO Vacuumed table table=pending_closures10802026/10/14 16:46:48 INFO Vacuumed table table=pending_objects10812026/10/14 16:46:48 INFO Vacuumed table table=multipart_uploads10822026/10/14 16:46:48 INFO Vacuumed table table=closures10832026/10/14 16:46:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10842026/10/14 16:46:48 INFO Vacuumed table table=objects10852026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures10862026/10/14 16:46:48 INFO Aborted multipart uploads count=0 kept=01087--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.89s)1088=== CONT TestReadRedirectNar1089--- PASS: TestGCSweepSkipsPendingObjects (0.88s)1090=== CONT TestReadProxyDisabled10912026/10/14 16:46:48 WARN Force mode enabled - objects will be deleted immediately without grace period10922026/10/14 16:46:48 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=010932026/10/14 16:46:48 INFO Vacuumed table table=pending_closures10942026/10/14 16:46:48 INFO Vacuumed table table=pending_objects10952026/10/14 16:46:48 INFO Vacuumed table table=multipart_uploads10962026/10/14 16:46:48 INFO Vacuumed table table=closures10972026/10/14 16:46:48 INFO Vacuumed table table=objects10982026/10/14 16:46:48 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZjM2ODBiNzYtMGZiOS00OGRmLTk2NmQtMmFmNjI2OTMzNzdiLjRmN2ZkNDkxLTRmOGItNDllZi1hYjg3LWMwYTU3MWI5ZWYxYXgxNzkxOTk2NDA3ODY4Njk4NzI1 parts=101099--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.99s)11002026/10/14 16:46:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1101=== CONT TestCreatePendingClosureRejectsOversizedNAR11022026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures1103--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1104=== CONT TestParseSingleRange1105=== RUN TestParseSingleRange/none1106=== PAUSE TestParseSingleRange/none1107=== RUN TestParseSingleRange/unknown_unit1108=== PAUSE TestParseSingleRange/unknown_unit1109=== RUN TestParseSingleRange/multi-range_ignored1110=== PAUSE TestParseSingleRange/multi-range_ignored1111=== RUN TestParseSingleRange/malformed_no_dash1112=== PAUSE TestParseSingleRange/malformed_no_dash1113=== RUN TestParseSingleRange/malformed_both_empty1114=== PAUSE TestParseSingleRange/malformed_both_empty1115=== RUN TestParseSingleRange/malformed_end_before_start1116=== PAUSE TestParseSingleRange/malformed_end_before_start1117=== RUN TestParseSingleRange/closed1118=== PAUSE TestParseSingleRange/closed1119=== RUN TestParseSingleRange/open-ended1120=== PAUSE TestParseSingleRange/open-ended1121=== RUN TestParseSingleRange/end_clamped_to_size1122=== PAUSE TestParseSingleRange/end_clamped_to_size1123=== RUN TestParseSingleRange/suffix1124=== PAUSE TestParseSingleRange/suffix1125=== RUN TestParseSingleRange/suffix_exceeds_size1126=== PAUSE TestParseSingleRange/suffix_exceeds_size1127=== RUN TestParseSingleRange/single_byte1128=== PAUSE TestParseSingleRange/single_byte1129=== RUN TestParseSingleRange/start_past_EOF1130=== PAUSE TestParseSingleRange/start_past_EOF1131=== RUN TestParseSingleRange/start_far_past_EOF1132=== PAUSE TestParseSingleRange/start_far_past_EOF1133--- PASS: TestGCMetrics (0.67s)1134=== CONT TestPresentNotReportedWhileGCDeletesClosure1135=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1136=== CONT TestPresentRefreshesOnlyStaleClosures1137=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1138=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1139=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1140=== CONT TestPresentReportsOnlyClosureRoots11412026/10/14 16:46:48 INFO Completed upload id=1 objects=2 duration=4.564287ms11422026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures11432026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures11442026/10/14 16:46:48 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11452026/10/14 16:46:48 WARN Found objects in DB but missing from S3, will re-upload count=11146--- PASS: TestService_verifyS3Integrity (1.01s)1147=== CONT TestCreatePin_ReservedPins11482026/10/14 16:46:48 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"1149--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.62s)1150=== CONT TestOrphanedObjectsGCStressTest11512026/10/14 16:46:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11522026/10/14 16:46:48 INFO Aborted multipart uploads count=0 kept=011532026/10/14 16:46:48 INFO lead: acquired remote=192.0.2.1:123411542026/10/14 16:46:48 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=011552026/10/14 16:46:48 INFO Vacuumed table table=pending_closures11562026/10/14 16:46:48 INFO Vacuumed table table=pending_objects11572026/10/14 16:46:48 INFO Vacuumed table table=multipart_uploads11582026/10/14 16:46:48 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZjM2ODBiNzYtMGZiOS00OGRmLTk2NmQtMmFmNjI2OTMzNzdiLjg0MjFmYTU2LTlhYzMtNDA4MS1iNDA5LTVmZDVhNmZkYzMyZXgxNzkxOTk2NDA3OTQ0NDM2ODQ2 parts=1011592026/10/14 16:46:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11602026/10/14 16:46:48 INFO Vacuumed table table=closures11612026/10/14 16:46:48 INFO Completed upload id=1 objects=2 duration=4.953097ms11622026/10/14 16:46:48 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011632026/10/14 16:46:48 INFO Vacuumed table table=objects11642026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures11652026/10/14 16:46:48 INFO lead: acquired remote=192.0.2.1:123411662026/10/14 16:46:48 INFO lead: released remote=192.0.2.1:12341167--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.58s)1168=== CONT TestOrphanedObjectsGC11692026/10/14 16:46:48 INFO Aborted multipart uploads count=0 kept=011702026/10/14 16:46:48 INFO Starting cleanup of old closures method=DELETE path=/api/closures11712026/10/14 16:46:48 WARN Force mode enabled - objects will be deleted immediately without grace period11722026/10/14 16:46:48 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=011732026/10/14 16:46:48 INFO Vacuumed table table=pending_closures11742026/10/14 16:46:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40187/oidc11752026/10/14 16:46:48 INFO Vacuumed table table=pending_objects11762026/10/14 16:46:48 INFO Vacuumed table table=multipart_uploads11772026/10/14 16:46:48 INFO Vacuumed table table=closures11782026/10/14 16:46:48 INFO Aborted multipart uploads count=0 kept=011792026/10/14 16:46:48 INFO Vacuumed table table=objects1180--- PASS: TestPushDedupSurvivesConcurrentGC (0.80s)1181=== CONT TestObjectStatsLargeCommit11822026/10/14 16:46:48 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=011832026/10/14 16:46:48 INFO lead: acquired remote=192.0.2.1:123411842026/10/14 16:46:48 INFO Vacuumed table table=pending_closures11852026/10/14 16:46:48 INFO Vacuumed table table=pending_objects11862026/10/14 16:46:48 INFO Vacuumed table table=multipart_uploads11872026/10/14 16:46:48 INFO Vacuumed table table=closures11882026/10/14 16:46:48 INFO Vacuumed table table=objects11892026/10/14 16:46:48 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001190--- PASS: TestService_createPendingClosureHandler (1.14s)1191=== CONT TestObjectStatsTrigger1192--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.54s)1193=== CONT TestPendingCleanupUsesOneCutoff11942026/10/14 16:46:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11952026/10/14 16:46:48 INFO Received push request method=POST path=/api/pushes11962026/10/14 16:46:48 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZjM2ODBiNzYtMGZiOS00OGRmLTk2NmQtMmFmNjI2OTMzNzdiLjJiMjZhYmI4LTdiYjctNDk2Mi04NWVmLTE1ZTQ1ZjJjNmYwNngxNzkxOTk2NDA3OTcxNDIzMTE4 parts=1211972026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures11982026/10/14 16:46:48 INFO Received push request method=POST path=/api/pushes11992026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures12002026/10/14 16:46:48 INFO Received complete push request method=POST path=/api/pushes/1/complete12012026/10/14 16:46:48 INFO Received push request method=POST path=/api/pushes12022026/10/14 16:46:48 INFO Completed push id=1 objects=4 duration=7.561665ms1203--- PASS: TestPush_RepeatedRootCommitsOnce (0.52s)1204=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded12052026/10/14 16:46:48 INFO Received complete push request method=POST path=/api/pushes/1/complete1206--- PASS: TestGCBugBareHashReferences (0.90s)1207=== CONT TestMultipartCleanup12082026/10/14 16:46:48 INFO Completed push id=1 objects=6 duration=7.354675ms12092026/10/14 16:46:48 INFO Received push request method=POST path=/api/pushes1210--- PASS: TestPush_CompleteCommitsEveryRoot (0.48s)1211=== CONT TestServerTLSConfig1212=== RUN TestServerTLSConfig/no_client_CA1213=== PAUSE TestServerTLSConfig/no_client_CA1214=== RUN TestServerTLSConfig/missing_CA_file1215=== PAUSE TestServerTLSConfig/missing_CA_file1216=== RUN TestServerTLSConfig/not_a_PEM_file1217=== PAUSE TestServerTLSConfig/not_a_PEM_file1218=== CONT TestService_NativeMTLS12192026/10/14 16:46:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1220--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.50s)1221=== CONT TestMetricsCommit1222--- PASS: TestReadRedirectUsesPublicS3URL (0.43s)1223=== CONT TestMetricsInventory12242026/10/14 16:46:48 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZjM2ODBiNzYtMGZiOS00OGRmLTk2NmQtMmFmNjI2OTMzNzdiLjY3YjdmNTNmLWFhN2QtNGQ1Ni05NmNmLWNlMzU0ZDQ0NWI0ZHgxNzkxOTk2NDA4MDYxMjQzOTk5 parts=1212252026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures1226--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.33s)1227=== CONT TestClientErrorHandling1228=== RUN TestClientErrorHandling/InvalidStorePath1229=== PAUSE TestClientErrorHandling/InvalidStorePath1230=== RUN TestClientErrorHandling/InvalidAuthToken1231=== PAUSE TestClientErrorHandling/InvalidAuthToken1232=== RUN TestClientErrorHandling/ServerNotAvailable1233=== PAUSE TestClientErrorHandling/ServerNotAvailable1234=== CONT TestNARDeduplicationMetadataUploadBug1235--- PASS: TestReadProxyRangeRequest (0.42s)1236=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1237--- PASS: TestReadRedirectKeepsNarinfoProxied (0.40s)1238=== CONT TestReadProxy4041239--- PASS: TestReadRedirectNar (0.41s)1240=== CONT TestReadProxyConditionalGet1241--- PASS: TestReadProxyDisabled (0.44s)1242=== CONT TestDeleteClosuresRacingPins1243--- PASS: TestPresentRefreshesOnlyStaleClosures (0.50s)1244=== CONT TestReadProxyOutlastsServerWriteTimeout12452026-10-14 16:46:48.817 UTC [785] ERROR: Push does not exist: id=112462026-10-14 16:46:48.817 UTC [785] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE12472026-10-14 16:46:48.817 UTC [785] STATEMENT: SELECT commit_push($1)1248--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.87s)1249=== CONT TestClientFallsBackToClosures1250--- PASS: TestPresentReportsOnlyClosureRoots (0.54s)1251=== CONT TestReadProxyHead12522026/10/14 16:46:48 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12532026/10/14 16:46:48 WARN Refused reserved pin name=worker-x86_64-linux12542026/10/14 16:46:48 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12552026/10/14 16:46:48 INFO Received create pin request method=POST path=/api/pins/my-app12562026/10/14 16:46:48 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1257--- PASS: TestCreatePin_ReservedPins (0.62s)1258=== CONT TestClientPushesUseOnePush1259--- PASS: TestObjectStatsTrigger (0.52s)1260=== CONT TestReadProxyInvalidPath12612026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures12622026/10/14 16:46:48 INFO Received uploads request method=POST path=/api/pending_closures12632026/10/14 16:46:49 INFO Received cleanup request method=DELETE path=/api/pending_closures12642026/10/14 16:46:49 INFO Received uploads request method=POST path=/api/pending_closures1265--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.47s)1266=== CONT TestPinProtectsFromGC12672026/10/14 16:46:49 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12682026/10/14 16:46:49 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1269--- PASS: TestService_NativeMTLS (0.46s)1270=== CONT TestClientSharedPathCommittedMidPush12712026/10/14 16:46:49 INFO Received uploads request method=POST path=/api/pending_closures12722026/10/14 16:46:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12732026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes12742026/10/14 16:46:49 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZjM2ODBiNzYtMGZiOS00OGRmLTk2NmQtMmFmNjI2OTMzNzdiLjY0ZTkxMTVhLWY1NWEtNDE2YS04ZGJjLWIyMjAzYjJiYWFiOHgxNzkxOTk2NDA4NTMyNjY2MzUx error="Get \"http://127.0.0.1:1/bucket17/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"12752026/10/14 16:46:49 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZjM2ODBiNzYtMGZiOS00OGRmLTk2NmQtMmFmNjI2OTMzNzdiLmRlZjMwZWRkLTAyY2QtNGEyMi1hZDFiLTBhNmMyNjMyZTIxNHgxNzkxOTk2NDA4NTI0MTUxNTQ3 parts=1212762026/10/14 16:46:49 INFO Received cleanup request method=DELETE path=/api/pending_closures12772026/10/14 16:46:49 INFO Aborted multipart uploads count=1 kept=012782026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/1/complete1279--- PASS: TestRedundantMultipartUpload (1.78s)1280=== CONT TestService_RequireScope_OIDC12812026/10/14 16:46:49 INFO Completed push id=1 objects=4 duration=8.215605ms12822026/10/14 16:46:49 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12832026/10/14 16:46:49 INFO Completed upload id=2 objects=2 duration=1.263119ms1284--- PASS: TestMetricsCommit (0.53s)1285=== CONT TestClientWithDependencies1286--- PASS: TestMetricsInventory (0.52s)1287=== CONT TestClientMultipleUploads12882026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes12892026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/1/complete12902026/10/14 16:46:49 INFO Received cleanup request method=DELETE path=/api/pending_closures12912026/10/14 16:46:49 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket55/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12922026/10/14 16:46:49 INFO Aborted multipart uploads count=0 kept=112932026/10/14 16:46:49 INFO Completed push id=1 objects=4 duration=8.239665ms12942026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes12952026/10/14 16:46:49 INFO Received cleanup request method=DELETE path=/api/pending_closures12962026/10/14 16:46:49 INFO Aborted multipart uploads count=1 kept=01297--- PASS: TestMultipartCleanup (0.62s)1298=== CONT TestClientIntegration1299=== NAME TestNARDeduplicationMetadataUploadBug1300 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug3276716731/001/store/2qdcgmfmjchblnhr9ybwl4qp1lvi0k0g-file1.txt1301--- PASS: TestReadProxy404 (0.56s)1302=== CONT TestClientCADerivations13032026/10/14 16:46:49 INFO Aborted multipart uploads count=0 kept=01304--- PASS: TestReadProxyConditionalGet (0.54s)1305=== CONT TestCacheConfigHandler1306=== RUN TestCacheConfigHandler/full_config,_no_issuer1307=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1308=== RUN TestCacheConfigHandler/no_cache_url_configured1309=== PAUSE TestCacheConfigHandler/no_cache_url_configured1310=== RUN TestCacheConfigHandler/no_signing_keys1311=== PAUSE TestCacheConfigHandler/no_signing_keys1312=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1313=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1314=== CONT TestCacheStatsHandler1315=== NAME TestOrphanedObjectsGC1316 orphaned_objects_gc_test.go:287: GC Test Summary:1317 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1318 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1319 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1320 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1321 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1322--- PASS: TestOrphanedObjectsGC (0.85s)13232026/10/14 16:46:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37255/oidc1324=== CONT TestService_ReadScope_PublicByDefault13252026/10/14 16:46:49 WARN Force mode enabled - objects will be deleted immediately without grace period13262026/10/14 16:46:49 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=013272026/10/14 16:46:49 INFO Vacuumed table table=pending_closures13282026/10/14 16:46:49 INFO Vacuumed table table=pending_objects13292026/10/14 16:46:49 INFO Vacuumed table table=multipart_uploads13302026/10/14 16:46:49 INFO Vacuumed table table=closures13312026/10/14 16:46:49 INFO Vacuumed table table=objects13322026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/2/complete13332026/10/14 16:46:49 INFO Completed push id=2 objects=4 duration=4.224197ms1334--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.65s)1335=== CONT TestService_healthCheckHandler13362026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes13372026/10/14 16:46:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13382026/10/14 16:46:49 INFO Uploading 2qdcgmfmjchblnhr9ybwl4qp1lvi0k0g-file1.txt (160B)13392026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"13402026/10/14 16:46:49 WARN Failed to register uploaded object key=2qdcgmfmjchblnhr9ybwl4qp1lvi0k0g.ls error="server returned 404: 404 page not found\n"13412026/10/14 16:46:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13422026/10/14 16:46:49 INFO Signed narinfos id=1 count=113432026/10/14 16:46:49 INFO Uploading 1 narinfos13442026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/1/complete13452026/10/14 16:46:49 WARN Failed to register uploaded object key=2qdcgmfmjchblnhr9ybwl4qp1lvi0k0g.narinfo error="server returned 404: 404 page not found\n"13462026/10/14 16:46:49 INFO Completed push id=1 objects=3 duration=10.488693ms13472026/10/14 16:46:49 INFO Upload complete. (85ms)1348=== NAME TestNARDeduplicationMetadataUploadBug1349 metadata_upload_test.go:54: Retrieved narinfo from S3:1350 StorePath: /build/TestNARDeduplicationMetadataUploadBug3276716731/001/store/2qdcgmfmjchblnhr9ybwl4qp1lvi0k0g-file1.txt1351 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1352 Compression: zstd1353 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1354 NarSize: 1601355 References: 1356 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1357 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1358 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1359 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1360--- PASS: TestReadProxyHead (0.51s)1361=== CONT TestCacheConfigHandlerMaxNarSize1362--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1363=== CONT TestGenerateLandingPage1364--- PASS: TestGenerateLandingPage (0.00s)1365=== CONT TestService_readinessHandler1366=== NAME TestNARDeduplicationMetadataUploadBug1367 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug3276716731/001/store/czdr9iiczc5p711qwva54m7f1xazgjyh-file2.txt1368--- PASS: TestReadProxyInvalidPath (0.43s)1369=== CONT TestGCEndsOnShutdown1370=== RUN TestGCEndsOnShutdown/before_the_run1371=== PAUSE TestGCEndsOnShutdown/before_the_run1372=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1373=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1374=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1375=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1376=== CONT TestGCTaskStore_GetReturnsLatest1377--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1378=== CONT TestGCTaskStore_GetEmpty1379--- PASS: TestGCTaskStore_GetEmpty (0.00s)1380=== CONT TestReadProxyContentNegotiation13812026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes13822026/10/14 16:46:49 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13832026/10/14 16:46:49 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13842026/10/14 16:46:49 WARN Failed to register uploaded object key=czdr9iiczc5p711qwva54m7f1xazgjyh.ls error="server returned 404: 404 page not found\n"13852026/10/14 16:46:49 INFO Signed narinfos id=2 count=113862026/10/14 16:46:49 INFO Uploading 1 narinfos13872026/10/14 16:46:49 INFO lead: released remote=192.0.2.1:12341388--- PASS: TestLeadEndsOnShutdown (1.73s)1389=== CONT TestGCTaskStore_ConflictDifferentParams1390--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1391=== CONT TestReadProxyNarStreaming13922026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/2/complete13932026/10/14 16:46:49 WARN Failed to register uploaded object key=czdr9iiczc5p711qwva54m7f1xazgjyh.narinfo error="server returned 404: 404 page not found\n"13942026/10/14 16:46:49 INFO Completed push id=2 objects=3 duration=2.525558ms13952026/10/14 16:46:49 INFO Upload complete. (56ms)1396=== NAME TestNARDeduplicationMetadataUploadBug1397 metadata_upload_test.go:76: Retrieved narinfo from S3:1398 StorePath: /build/TestNARDeduplicationMetadataUploadBug3276716731/001/store/czdr9iiczc5p711qwva54m7f1xazgjyh-file2.txt1399 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1400 Compression: zstd1401 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1402 NarSize: 1601403 References: 1404 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1405 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1406 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1407 {"version":1,"root":{"type":"regular","size":44}}14082026/10/14 16:46:49 INFO Received uploads request method=POST path=/api/pending_closures1409--- PASS: TestNARDeduplicationMetadataUploadBug (0.84s)1410=== CONT TestGCTaskStore_DeduplicateSameParams1411--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1412=== CONT TestGCTaskStore_PhaseUpdates1413--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1414=== CONT TestGCTaskStore_StartNew1415--- PASS: TestGCTaskStore_StartNew (0.00s)1416=== CONT TestGracefulShutdownDrainsInflight14172026/10/14 16:46:49 INFO Starting HTTP server address=127.0.0.1:4067914182026/10/14 16:46:49 INFO Shutdown signal received, draining in-flight requests timeout=10s14192026/10/14 16:46:49 INFO Received uploads request method=POST path=/api/pending_closures14202026/10/14 16:46:49 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14212026/10/14 16:46:49 INFO Uploading wnglmjf31acr41a7d5j9vw1dmr768jam-a (216B)14222026/10/14 16:46:49 INFO Uploading 19j6956bj7bbv5212y663712fwsrw18y-shared-dep (136B)14232026/10/14 16:46:49 WARN Failed to register uploaded object key=myygl7qvlsxg07fs23pgrw670kxh4ji5.ls error="server returned 404: 404 page not found\n"14242026/10/14 16:46:49 WARN Failed to register uploaded object key=19j6956bj7bbv5212y663712fwsrw18y.ls error="server returned 404: 404 page not found\n"14252026/10/14 16:46:49 WARN Failed to register uploaded object key=wnglmjf31acr41a7d5j9vw1dmr768jam.ls error="server returned 404: 404 page not found\n"14262026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14272026/10/14 16:46:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14282026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/0jlnkdz7msy0qsnr2f3wb44lcs0fzpbrap74jmc0y58fsawrb7s0.nar.zst error="server returned 404: 404 page not found\n"14292026/10/14 16:46:49 INFO Signed narinfos id=1 count=214302026/10/14 16:46:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14312026/10/14 16:46:49 INFO Signed narinfos id=2 count=214322026/10/14 16:46:49 INFO Uploading 4 narinfos1433=== NAME TestPinProtectsFromGC1434 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC2059348664/001/store/hd2z9b2m9ragzymq8rn6nnhf5d84dp6j-pinned-file.txt1435 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC2059348664/001/store/wn28xlpa4gm08jfk8fg29zdpz8r6fknf-unpinned-file.txt14362026/10/14 16:46:49 WARN Failed to register uploaded object key=19j6956bj7bbv5212y663712fwsrw18y.narinfo error="server returned 404: 404 page not found\n"14372026/10/14 16:46:49 WARN Failed to register uploaded object key=myygl7qvlsxg07fs23pgrw670kxh4ji5.narinfo error="server returned 404: 404 page not found\n"14382026/10/14 16:46:49 WARN Failed to register uploaded object key=wnglmjf31acr41a7d5j9vw1dmr768jam.narinfo error="server returned 404: 404 page not found\n"14392026/10/14 16:46:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14402026/10/14 16:46:49 WARN Failed to register uploaded object key=19j6956bj7bbv5212y663712fwsrw18y.narinfo error="server returned 404: 404 page not found\n"14412026/10/14 16:46:49 INFO Completed upload id=1 objects=6 duration=7.994585ms14422026/10/14 16:46:49 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14432026/10/14 16:46:49 INFO Completed upload id=2 objects=6 duration=2.420528ms14442026/10/14 16:46:49 INFO Upload complete. (89ms)1445=== NAME TestClientFallsBackToClosures1446 client_pushes_test.go:112: Retrieved narinfo from S3:1447 StorePath: /build/TestClientFallsBackToClosures924468294/001/store/19j6956bj7bbv5212y663712fwsrw18y-shared-dep1448 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1449 Compression: zstd1450 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821451 NarSize: 1361452 References: 1453 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1454 client_pushes_test.go:112: Retrieved narinfo from S3:1455 StorePath: /build/TestClientFallsBackToClosures924468294/001/store/wnglmjf31acr41a7d5j9vw1dmr768jam-a1456 URL: nar/0jlnkdz7msy0qsnr2f3wb44lcs0fzpbrap74jmc0y58fsawrb7s0.nar.zst1457 Compression: zstd1458 NarHash: sha256:0jlnkdz7msy0qsnr2f3wb44lcs0fzpbrap74jmc0y58fsawrb7s01459 NarSize: 2161460 References: /build/TestClientFallsBackToClosures924468294/001/store/19j6956bj7bbv5212y663712fwsrw18y-shared-dep1461 CA: text:sha256:1k4d79353awk0drh3008mf2v15qvz5d4jv4ivv1dmvz1prr716ps1462 client_pushes_test.go:112: Retrieved narinfo from S3:1463 StorePath: /build/TestClientFallsBackToClosures924468294/001/store/myygl7qvlsxg07fs23pgrw670kxh4ji5-b1464 URL: nar/0jlnkdz7msy0qsnr2f3wb44lcs0fzpbrap74jmc0y58fsawrb7s0.nar.zst1465 Compression: zstd1466 NarHash: sha256:0jlnkdz7msy0qsnr2f3wb44lcs0fzpbrap74jmc0y58fsawrb7s01467 NarSize: 2161468 References: /build/TestClientFallsBackToClosures924468294/001/store/19j6956bj7bbv5212y663712fwsrw18y-shared-dep1469 CA: text:sha256:1k4d79353awk0drh3008mf2v15qvz5d4jv4ivv1dmvz1prr716ps1470--- PASS: TestClientFallsBackToClosures (0.73s)1471=== CONT TestGCTaskStore_Fail1472--- PASS: TestGCTaskStore_Fail (0.00s)1473=== CONT TestGCTaskStore_CompletedAllowsNewTask1474--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1475=== CONT TestService_ReadAuthMiddleware1476--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1477=== CONT TestReadProxyNarinfoAlreadyDecompressed1478=== NAME TestClientMultipleUploads1479 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads2733901138/001/store/m7dlc9l9d327qgbril9chq17k93pspbi-test-file-0.txt14802026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes14812026/10/14 16:46:49 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14822026/10/14 16:46:49 INFO Uploading arz2wf6ry6qqq2pq9x8cqyr0zj7hm2ng-a (216B)14832026/10/14 16:46:49 INFO Uploading myrdic404a87az4a85cv7fbrq9hrhdjl-shared-dep (136B)1484=== NAME TestClientWithDependencies1485 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies3928130386/001/store/x9fy11jb2fdw6xbsy782r6k5hlmc2xpx-test-script14862026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes14872026/10/14 16:46:49 WARN Failed to register uploaded object key=3zhcljhnyghpgyrzx6fbyqvp8hszb5r7.ls error="server returned 404: 404 page not found\n"14882026/10/14 16:46:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14892026/10/14 16:46:49 INFO Uploading hd2z9b2m9ragzymq8rn6nnhf5d84dp6j-pinned-file.txt (128B)14902026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/0wybfv8v11ajlhiyvlycw71d1b18ygrh53l3rrkzn5v6zw6mnyvx.nar.zst error="server returned 404: 404 page not found\n"14912026/10/14 16:46:49 WARN Failed to register uploaded object key=arz2wf6ry6qqq2pq9x8cqyr0zj7hm2ng.ls error="server returned 404: 404 page not found\n"14922026/10/14 16:46:49 WARN Failed to register uploaded object key=myrdic404a87az4a85cv7fbrq9hrhdjl.ls error="server returned 404: 404 page not found\n"14932026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14942026/10/14 16:46:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14952026/10/14 16:46:49 INFO Signed narinfos id=1 count=314962026/10/14 16:46:49 INFO Uploading 3 narinfos14972026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14982026/10/14 16:46:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14992026/10/14 16:46:49 WARN Failed to register uploaded object key=hd2z9b2m9ragzymq8rn6nnhf5d84dp6j.ls error="server returned 404: 404 page not found\n"15002026/10/14 16:46:49 INFO Signed narinfos id=1 count=115012026/10/14 16:46:49 INFO Uploading 1 narinfos15022026/10/14 16:46:49 WARN Failed to register uploaded object key=myrdic404a87az4a85cv7fbrq9hrhdjl.narinfo error="server returned 404: 404 page not found\n"15032026/10/14 16:46:49 WARN Failed to register uploaded object key=3zhcljhnyghpgyrzx6fbyqvp8hszb5r7.narinfo error="server returned 404: 404 page not found\n"15042026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/1/complete15052026/10/14 16:46:49 WARN Failed to register uploaded object key=arz2wf6ry6qqq2pq9x8cqyr0zj7hm2ng.narinfo error="server returned 404: 404 page not found\n"1506=== NAME TestClientIntegration1507 client_integration_test.go:286: Created store path: /build/TestClientIntegration1436382783/002/store/myx002ja7hj3ji1hfqkj46arq1lqi6c9-test-file.txt15082026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/1/complete15092026/10/14 16:46:49 WARN Failed to register uploaded object key=hd2z9b2m9ragzymq8rn6nnhf5d84dp6j.narinfo error="server returned 404: 404 page not found\n"15102026/10/14 16:46:49 INFO Completed push id=1 objects=8 duration=7.656575ms15112026/10/14 16:46:49 INFO Upload complete. (72ms)1512=== NAME TestClientMultipleUploads1513 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads2733901138/001/store/9sfwbinmj1z38bky8yq3i2ba48nm5y01-test-file-1.txt15142026/10/14 16:46:49 INFO Completed push id=1 objects=3 duration=6.546186ms15152026/10/14 16:46:49 INFO Upload complete. (61ms)1516=== NAME TestClientPushesUseOnePush1517 client_pushes_test.go:97: Retrieved narinfo from S3:1518 StorePath: /build/TestClientPushesUseOnePush3601009904/001/store/myrdic404a87az4a85cv7fbrq9hrhdjl-shared-dep1519 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1520 Compression: zstd1521 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821522 NarSize: 1361523 References: 1524 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1525 client_pushes_test.go:97: Retrieved narinfo from S3:1526 StorePath: /build/TestClientPushesUseOnePush3601009904/001/store/arz2wf6ry6qqq2pq9x8cqyr0zj7hm2ng-a1527 URL: nar/0wybfv8v11ajlhiyvlycw71d1b18ygrh53l3rrkzn5v6zw6mnyvx.nar.zst1528 Compression: zstd1529 NarHash: sha256:0wybfv8v11ajlhiyvlycw71d1b18ygrh53l3rrkzn5v6zw6mnyvx1530 NarSize: 2161531 References: /build/TestClientPushesUseOnePush3601009904/001/store/myrdic404a87az4a85cv7fbrq9hrhdjl-shared-dep1532 CA: text:sha256:1z94b8fh3lh51y02xjh2cka2rzqq9xbilxbwybid3vy48ccqgllj1533 client_pushes_test.go:97: Retrieved narinfo from S3:1534 StorePath: /build/TestClientPushesUseOnePush3601009904/001/store/3zhcljhnyghpgyrzx6fbyqvp8hszb5r7-b1535 URL: nar/0wybfv8v11ajlhiyvlycw71d1b18ygrh53l3rrkzn5v6zw6mnyvx.nar.zst1536 Compression: zstd1537 NarHash: sha256:0wybfv8v11ajlhiyvlycw71d1b18ygrh53l3rrkzn5v6zw6mnyvx1538 NarSize: 2161539 References: /build/TestClientPushesUseOnePush3601009904/001/store/myrdic404a87az4a85cv7fbrq9hrhdjl-shared-dep1540 CA: text:sha256:1z94b8fh3lh51y02xjh2cka2rzqq9xbilxbwybid3vy48ccqgllj1541=== NAME TestClientWithDependencies1542 client_integration_test.go:615: Found 1 dependencies (including self)15432026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes1544--- PASS: TestClientPushesUseOnePush (0.67s)1545=== CONT TestReadProxyNarinfo15462026/10/14 16:46:49 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15472026/10/14 16:46:49 INFO Uploading dygahb5pr0y5ymm7rlain5kx4q17im7w-top (224B)15482026/10/14 16:46:49 INFO Uploading dayzg0sz7dvbr2s7a105v2r5xyzzv5ia-shared-dep (136B)1549--- PASS: TestCacheStatsHandler (0.38s)1550=== CONT TestPushWaitsForSweepHoldingRow15512026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15522026/10/14 16:46:49 WARN Failed to register uploaded object key=dygahb5pr0y5ymm7rlain5kx4q17im7w.ls error="server returned 404: 404 page not found\n"15532026/10/14 16:46:49 WARN Failed to register uploaded object key=dayzg0sz7dvbr2s7a105v2r5xyzzv5ia.ls error="server returned 404: 404 page not found\n"15542026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/1rmxm8z459d6lfm2kc2rbr3mcq4wcpp6g7mki7ffnq34w25ycb75.nar.zst error="server returned 404: 404 page not found\n"15552026/10/14 16:46:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15562026/10/14 16:46:49 INFO Signed narinfos id=1 count=215572026/10/14 16:46:49 INFO Uploading 2 narinfos15582026/10/14 16:46:49 INFO lead: released remote=192.0.2.1:123415592026/10/14 16:46:49 WARN Failed to register uploaded object key=dayzg0sz7dvbr2s7a105v2r5xyzzv5ia.narinfo error="server returned 404: 404 page not found\n"1560=== NAME TestClientMultipleUploads1561 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads2733901138/001/store/pycd6sfic7w3qika7fsnrh64c5d98jzl-test-file-2.txt1562--- PASS: TestService_ReadScope_PublicByDefault (0.38s)1563=== CONT TestCommitRacingPendingCleanupKeepsObjects15642026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/1/complete15652026/10/14 16:46:49 WARN Failed to register uploaded object key=dygahb5pr0y5ymm7rlain5kx4q17im7w.narinfo error="server returned 404: 404 page not found\n"15662026/10/14 16:46:49 INFO Completed push id=1 objects=6 duration=9.639444ms15672026/10/14 16:46:49 INFO Upload complete. (71ms)1568=== NAME TestClientSharedPathCommittedMidPush1569 client_integration_test.go:680: Retrieved narinfo from S3:1570 StorePath: /build/TestClientSharedPathCommittedMidPush548535852/001/store/dayzg0sz7dvbr2s7a105v2r5xyzzv5ia-shared-dep1571 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1572 Compression: zstd1573 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821574 NarSize: 1361575 References: 1576 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1577 client_integration_test.go:680: Retrieved narinfo from S3:1578 StorePath: /build/TestClientSharedPathCommittedMidPush548535852/001/store/dygahb5pr0y5ymm7rlain5kx4q17im7w-top1579 URL: nar/1rmxm8z459d6lfm2kc2rbr3mcq4wcpp6g7mki7ffnq34w25ycb75.nar.zst1580 Compression: zstd1581 NarHash: sha256:1rmxm8z459d6lfm2kc2rbr3mcq4wcpp6g7mki7ffnq34w25ycb751582 NarSize: 2241583 References: /build/TestClientSharedPathCommittedMidPush548535852/001/store/dayzg0sz7dvbr2s7a105v2r5xyzzv5ia-shared-dep1584 CA: text:sha256:1r358xfr8ai87a5j7yas845w6amqi6amcdy53srbp0hcrf0wfxd41585--- PASS: TestClientSharedPathCommittedMidPush (0.63s)1586=== CONT TestSweepRechecksPendingAfterLocking15872026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes15882026/10/14 16:46:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15892026/10/14 16:46:49 INFO Uploading myx002ja7hj3ji1hfqkj46arq1lqi6c9-test-file.txt (152B)15902026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes1591=== NAME TestClientCADerivations1592 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2246460345/001/store/lzxxn1j7h4k7zhhpnymyxf2wn6xl9n7w-ca-test15932026/10/14 16:46:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15942026/10/14 16:46:49 INFO Uploading wn28xlpa4gm08jfk8fg29zdpz8r6fknf-unpinned-file.txt (128B)15952026/10/14 16:46:49 WARN Failed to register uploaded object key=myx002ja7hj3ji1hfqkj46arq1lqi6c9.ls error="server returned 404: 404 page not found\n"15962026/10/14 16:46:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15972026/10/14 16:46:49 INFO Signed narinfos id=1 count=115982026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15992026/10/14 16:46:49 INFO Uploading 1 narinfos16002026/10/14 16:46:49 WARN Failed to register uploaded object key=wn28xlpa4gm08jfk8fg29zdpz8r6fknf.ls error="server returned 404: 404 page not found\n"16012026/10/14 16:46:49 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16022026/10/14 16:46:49 INFO Signed narinfos id=2 count=116032026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16042026/10/14 16:46:49 INFO Uploading 1 narinfos16052026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/1/complete16062026/10/14 16:46:49 WARN Failed to register uploaded object key=myx002ja7hj3ji1hfqkj46arq1lqi6c9.narinfo error="server returned 404: 404 page not found\n"16072026/10/14 16:46:49 INFO lead: acquired remote=192.0.2.1:123416082026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/2/complete16092026/10/14 16:46:49 WARN Failed to register uploaded object key=wn28xlpa4gm08jfk8fg29zdpz8r6fknf.narinfo error="server returned 404: 404 page not found\n"1610=== RUN TestService_RequireScope_OIDC/builder_may_write1611=== PAUSE TestService_RequireScope_OIDC/builder_may_write1612=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1613=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1614=== RUN TestService_RequireScope_OIDC/ops_may_admin1615=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1616=== RUN TestService_RequireScope_OIDC/ops_may_not_write1617=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1618=== RUN TestService_RequireScope_OIDC/reader_may_not_write1619=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1620=== RUN TestService_RequireScope_OIDC/static_token_may_admin1621=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1622=== RUN TestService_RequireScope_OIDC/static_token_may_write1623=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1624=== RUN TestService_RequireScope_OIDC/reader_may_read1625=== PAUSE TestService_RequireScope_OIDC/reader_may_read1626=== RUN TestService_RequireScope_OIDC/writer_implies_read1627=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1628=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1629=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1630=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1631=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1632=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1633=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1634=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1635=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1636=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1637=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1638=== CONT TestGetExistingObjectsLocksRows1639--- PASS: TestService_healthCheckHandler (0.39s)1640=== CONT TestService_AuthMiddleware_MTLSBoundSubjects16412026/10/14 16:46:49 INFO Completed push id=2 objects=3 duration=7.750145ms16422026/10/14 16:46:49 INFO Upload complete. (55ms)16432026/10/14 16:46:49 INFO Completed push id=1 objects=3 duration=13.600441ms16442026/10/14 16:46:49 INFO Upload complete. (66ms)16452026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes1646=== NAME TestClientCADerivations1647 client_ca_test.go:139: Found 1 dependencies (including self)16482026/10/14 16:46:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16492026/10/14 16:46:49 INFO Uploading x9fy11jb2fdw6xbsy782r6k5hlmc2xpx-test-script (136B)16502026/10/14 16:46:49 WARN Failed to register uploaded object key=x9fy11jb2fdw6xbsy782r6k5hlmc2xpx.ls error="server returned 404: 404 page not found\n"16512026/10/14 16:46:49 WARN Failed to register uploaded object key=log/bzb13564r03gr9x6vfq61nkqqbr4kn71-test-script.drv error="server returned 404: 404 page not found\n"16522026/10/14 16:46:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16532026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"16542026/10/14 16:46:49 INFO Signed narinfos id=1 count=116552026/10/14 16:46:49 INFO Uploading 1 narinfos16562026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/1/complete16572026/10/14 16:46:49 WARN Failed to register uploaded object key=x9fy11jb2fdw6xbsy782r6k5hlmc2xpx.narinfo error="server returned 404: 404 page not found\n"16582026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes16592026/10/14 16:46:49 WARN readiness check failed error="closed pool"1660--- PASS: TestService_readinessHandler (0.36s)1661=== CONT TestService_AuthMiddleware_MTLSProxyHeader16622026/10/14 16:46:49 INFO Completed push id=1 objects=4 duration=14.61836ms16632026/10/14 16:46:49 INFO Upload complete. (70ms)1664=== NAME TestClientWithDependencies1665 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3928130386/001/store) requires matching store prefix16662026/10/14 16:46:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures16672026/10/14 16:46:49 INFO Garbage collection started16682026/10/14 16:46:49 INFO All 1 paths already cached1669=== NAME TestClientIntegration1670 client_integration_test.go:312: Retrieved narinfo from S3:1671 StorePath: /build/TestClientIntegration1436382783/002/store/myx002ja7hj3ji1hfqkj46arq1lqi6c9-test-file.txt1672 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1673 Compression: zstd1674 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11675 NarSize: 1521676 References: 1677 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk116782026/10/14 16:46:49 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16792026/10/14 16:46:49 INFO Uploading m7dlc9l9d327qgbril9chq17k93pspbi-test-file-0.txt (160B)16802026/10/14 16:46:49 INFO Uploading 9sfwbinmj1z38bky8yq3i2ba48nm5y01-test-file-1.txt (160B)16812026/10/14 16:46:49 INFO Uploading pycd6sfic7w3qika7fsnrh64c5d98jzl-test-file-2.txt (160B)1682 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1683 client_integration_test.go:313: Decompressed .ls content (64 bytes):1684 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1685 client_integration_test.go:316: Testing garbage collection...1686--- PASS: TestClientWithDependencies (0.61s)1687=== CONT TestService_AuthMiddleware_OIDC16882026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"1689--- PASS: TestObjectStatsLargeCommit (1.32s)1690=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16912026/10/14 16:46:49 INFO Received uploads request method=POST path=/1692=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16932026/10/14 16:46:49 INFO Received request for more parts method=POST path=/16942026/10/14 16:46:49 WARN Failed to register uploaded object key=9sfwbinmj1z38bky8yq3i2ba48nm5y01.ls error="server returned 404: 404 page not found\n"1695=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16962026/10/14 16:46:49 WARN Failed to register uploaded object key=m7dlc9l9d327qgbril9chq17k93pspbi.ls error="server returned 404: 404 page not found\n"16972026/10/14 16:46:49 INFO Received complete multipart upload request method=POST path=/16982026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"1699=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17002026/10/14 16:46:49 WARN Failed to register uploaded object key=pycd6sfic7w3qika7fsnrh64c5d98jzl.ls error="server returned 404: 404 page not found\n"17012026/10/14 16:46:49 INFO Received uploads request method=POST path=/1702--- PASS: TestUploadHandlersRejectInvalidKeys (0.09s)1703 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1704 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1705 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1706 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1707=== CONT TestProxyWriteTimeout/narinfo17082026/10/14 16:46:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1709=== CONT TestProxyWriteTimeout/unknown_size17102026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"1711=== CONT TestProxyWriteTimeout/10_GiB_nar1712=== CONT TestProxyWriteTimeout/1_GiB_nar1713--- PASS: TestProxyWriteTimeout (0.09s)1714 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1715 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1716 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1717 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1718=== CONT TestPendingClosureWriteTimeout/empty1719=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline17202026/10/14 16:46:49 INFO Signed narinfos id=1 count=317212026/10/14 16:46:49 INFO Uploading 3 narinfos17222026/10/14 16:46:49 INFO Aborted multipart uploads count=0 kept=017232026/10/14 16:46:49 WARN Failed to register uploaded object key=pycd6sfic7w3qika7fsnrh64c5d98jzl.narinfo error="server returned 404: 404 page not found\n"17242026/10/14 16:46:49 WARN Failed to register uploaded object key=m7dlc9l9d327qgbril9chq17k93pspbi.narinfo error="server returned 404: 404 page not found\n"17252026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/1/complete17262026/10/14 16:46:49 WARN Failed to register uploaded object key=9sfwbinmj1z38bky8yq3i2ba48nm5y01.narinfo error="server returned 404: 404 page not found\n"17272026/10/14 16:46:49 WARN Force mode enabled - objects will be deleted immediately without grace period17282026/10/14 16:46:49 INFO Completed push id=1 objects=9 duration=12.118452ms17292026/10/14 16:46:49 INFO Upload complete. (87ms)1730=== NAME TestClientMultipleUploads1731 client_integration_test.go:369: Uploaded 3 paths in 130.649404ms17322026/10/14 16:46:49 INFO Starting cleanup of old closures method=DELETE path=/api/closures17332026/10/14 16:46:49 INFO Garbage collection started1734--- PASS: TestClientMultipleUploads (0.63s)1735=== CONT TestPendingClosureWriteTimeout/670k_objects1736=== CONT TestPendingClosureWriteTimeout/400_objects1737=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17382026/10/14 16:46:49 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=017392026/10/14 16:46:49 INFO Aborted multipart uploads count=0 kept=017402026/10/14 16:46:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35777/oidc17412026/10/14 16:46:49 WARN Force mode enabled - objects will be deleted immediately without grace period17422026/10/14 16:46:49 INFO Vacuumed table table=pending_closures1743--- PASS: TestReadProxyContentNegotiation (0.39s)1744=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1745--- PASS: TestReadProxyNarStreaming (0.35s)1746=== CONT TestIsValidCachePath/narinfo1747=== CONT TestIsValidCachePath/short_hash1748=== CONT TestIsValidCachePath/wrong_extension1749=== CONT TestIsValidCachePath/leading_slash1750=== CONT TestIsValidCachePath/empty1751=== CONT TestIsValidCachePath/random_path1752=== CONT TestIsValidCachePath/invalid_char_u1753=== CONT TestIsValidCachePath/invalid_char_e1754=== CONT TestIsValidCachePath/traversal_in_middle1755=== CONT TestIsValidCachePath/traversal_parent1756=== CONT TestIsValidCachePath/index.html1757=== CONT TestIsValidCachePath/nar_bz21758=== CONT TestIsValidCachePath/nar_xz1759=== CONT TestIsValidCachePath/nar_zst1760=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1761=== CONT TestIsValidCachePath/realisation1762=== CONT TestIsValidCachePath/nix-cache-info1763=== CONT TestIsValidCachePath/log1764=== CONT TestIsValidCachePath/nar_uncompressed1765=== CONT TestIsValidCachePath/ls1766--- PASS: TestIsValidCachePath (0.09s)1767 --- PASS: TestIsValidCachePath/narinfo (0.00s)1768 --- PASS: TestIsValidCachePath/short_hash (0.00s)1769 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1770 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1771 --- PASS: TestIsValidCachePath/empty (0.00s)1772 --- PASS: TestIsValidCachePath/random_path (0.00s)1773 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1774 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1775 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1776 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1777 --- PASS: TestIsValidCachePath/index.html (0.00s)1778 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1779 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1780 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1781 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1782 --- PASS: TestIsValidCachePath/realisation (0.00s)1783 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1784 --- PASS: TestIsValidCachePath/log (0.00s)1785 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1786 --- PASS: TestIsValidCachePath/ls (0.00s)1787=== CONT TestIsValidUploadKey/narinfo1788=== CONT TestIsValidUploadKey/realisation_plus_in_output1789=== CONT TestIsValidUploadKey/unknown_type1790=== CONT TestIsValidUploadKey/empty_key1791=== CONT TestIsValidUploadKey/absolute1792=== CONT TestIsValidUploadKey/traversal_nar1793=== CONT TestIsValidUploadKey/traversal17942026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes1795=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1796=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1797=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1798=== CONT TestIsValidUploadKey/index.html1799=== CONT TestIsValidUploadKey/nix-cache-info1800=== CONT TestIsValidUploadKey/build_log_home-manager_file1801=== CONT TestIsValidUploadKey/realisation1802=== CONT TestIsValidUploadKey/build_log_equals1803=== CONT TestIsValidUploadKey/build_log_question_mark1804=== CONT TestIsValidUploadKey/build_log_plus_in_name1805=== CONT TestIsValidUploadKey/build_log1806=== CONT TestIsValidUploadKey/listing1807=== CONT TestIsValidUploadKey/nar_xz1808=== CONT TestIsValidUploadKey/nar_zst1809=== CONT TestIsValidUploadKey/nar_plain1810--- PASS: TestIsValidUploadKey (0.09s)1811 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1812 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1813 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1814 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1815 --- PASS: TestIsValidUploadKey/absolute (0.00s)1816 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1817 --- PASS: TestIsValidUploadKey/traversal (0.00s)1818 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1819 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1820 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1821 --- PASS: TestIsValidUploadKey/index.html (0.00s)1822 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1823 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1824 --- PASS: TestIsValidUploadKey/realisation (0.00s)1825 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1826 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1827 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1828 --- PASS: TestIsValidUploadKey/build_log (0.00s)1829 --- PASS: TestIsValidUploadKey/listing (0.00s)1830 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1831 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1832 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1833=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18342026/10/14 16:46:49 INFO Received request for more parts method=POST path=/18352026/10/14 16:46:49 INFO Vacuumed table table=pending_objects18362026/10/14 16:46:49 INFO Vacuumed table table=multipart_uploads18372026/10/14 16:46:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18382026/10/14 16:46:49 INFO Uploading lzxxn1j7h4k7zhhpnymyxf2wn6xl9n7w-ca-test (144B)18392026/10/14 16:46:49 INFO Vacuumed table table=closures18402026/10/14 16:46:49 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=018412026/10/14 16:46:49 INFO Vacuumed table table=objects1842--- PASS: TestService_ReadAuthMiddleware (0.30s)1843=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18442026/10/14 16:46:49 INFO Received complete multipart upload request method=POST path=/18452026/10/14 16:46:49 WARN Failed to register uploaded object key=lzxxn1j7h4k7zhhpnymyxf2wn6xl9n7w.ls error="server returned 404: 404 page not found\n"18462026/10/14 16:46:49 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18472026/10/14 16:46:49 WARN Failed to register uploaded object key=log/azd412fk5lgnbs9m7jcmrlzfzx894sbb-ca-test.drv error="server returned 404: 404 page not found\n"18482026/10/14 16:46:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18492026/10/14 16:46:49 INFO Signed narinfos id=1 count=118502026/10/14 16:46:49 INFO Uploading 1 narinfos18512026/10/14 16:46:49 INFO Vacuumed table table=pending_closures18522026/10/14 16:46:49 INFO Received complete push request method=POST path=/api/pushes/1/complete18532026/10/14 16:46:49 WARN Failed to register uploaded object key=lzxxn1j7h4k7zhhpnymyxf2wn6xl9n7w.narinfo error="server returned 404: 404 page not found\n"18542026/10/14 16:46:49 INFO Vacuumed table table=pending_objects18552026/10/14 16:46:49 INFO Vacuumed table table=multipart_uploads18562026/10/14 16:46:49 INFO Vacuumed table table=closures18572026/10/14 16:46:49 INFO Completed push id=1 objects=4 duration=11.063083ms18582026/10/14 16:46:49 INFO Vacuumed table table=objects1859=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18602026/10/14 16:46:49 INFO Upload complete. (131ms)18612026/10/14 16:46:49 INFO Received uploads request method=POST path=/1862=== NAME TestClientCADerivations1863 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2246460345/001/store/lzxxn1j7h4k7zhhpnymyxf2wn6xl9n7w-ca-test1864 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1865 Compression: zstd1866 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1867 NarSize: 1441868 References: 1869 Deriver: /build/TestClientCADerivations2246460345/001/store/azd412fk5lgnbs9m7jcmrlzfzx894sbb-ca-test.drv1870 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1871 client_ca_test.go:185: Checking for realisation files in S3...1872 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1873 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1874--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.33s)1875=== CONT TestPush_RejectsBadRequests/no_roots18762026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes1877=== CONT TestPush_RejectsBadRequests/bad_root18782026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes1879=== CONT TestPush_RejectsBadRequests/root_not_in_objects18802026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes1881=== CONT TestPush_RejectsBadRequests/no_objects18822026/10/14 16:46:49 INFO Received push request method=POST path=/api/pushes1883=== CONT TestResolveDBConnectionString/flag_wins1884=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1885--- PASS: TestPush_RejectsBadRequests (0.33s)1886 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1887 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1888 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1889 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1890=== CONT TestResolveDBConnectionString/nothing_configured1891=== CONT TestResolveDBConnectionString/missing_file_is_an_error1892=== CONT TestResolveDBConnectionString/file_when_flag_empty1893=== CONT TestParseSingleRange/none1894=== CONT TestParseSingleRange/end_clamped_to_size1895=== CONT TestParseSingleRange/start_far_past_EOF1896=== CONT TestParseSingleRange/start_past_EOF1897=== CONT TestParseSingleRange/single_byte1898=== CONT TestParseSingleRange/suffix_exceeds_size1899=== CONT TestParseSingleRange/suffix1900=== CONT TestParseSingleRange/closed1901=== CONT TestParseSingleRange/open-ended1902=== CONT TestParseSingleRange/malformed_both_empty1903=== CONT TestParseSingleRange/malformed_end_before_start1904=== CONT TestParseSingleRange/multi-range_ignored1905=== CONT TestParseSingleRange/malformed_no_dash1906=== CONT TestParseSingleRange/unknown_unit1907=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1908--- PASS: TestResolveDBConnectionString (0.00s)1909 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1910 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1911 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1912 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1913 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1914--- PASS: TestParseSingleRange (0.00s)1915 --- PASS: TestParseSingleRange/none (0.00s)1916 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1917 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1918 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1919 --- PASS: TestParseSingleRange/single_byte (0.00s)1920 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1921 --- PASS: TestParseSingleRange/suffix (0.00s)1922 --- PASS: TestParseSingleRange/closed (0.00s)1923 --- PASS: TestParseSingleRange/open-ended (0.00s)1924 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1925 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1926 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1927 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1928 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1929=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh19302026/10/14 16:46:49 INFO Received uploads request method=POST path=/api/pending_closures19312026/10/14 16:46:49 INFO Aborted multipart uploads count=0 kept=019322026/10/14 16:46:49 WARN Force mode enabled - objects will be deleted immediately without grace period19332026/10/14 16:46:49 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=019342026/10/14 16:46:49 INFO Vacuumed table table=pending_closures19352026/10/14 16:46:49 INFO Vacuumed table table=pending_objects19362026/10/14 16:46:49 INFO Vacuumed table table=multipart_uploads19372026/10/14 16:46:49 INFO Vacuumed table table=closures19382026/10/14 16:46:49 INFO Vacuumed table table=objects1939--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.34s)1940=== CONT TestServerTLSConfig/no_client_CA1941=== CONT TestServerTLSConfig/not_a_PEM_file1942=== CONT TestServerTLSConfig/missing_CA_file1943--- PASS: TestServerTLSConfig (0.00s)1944 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1945 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1946 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1947=== CONT TestClientErrorHandling/InvalidStorePath1948=== NAME TestClientCADerivations1949 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1950 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1951 error: binary cache 's3://bucket73?endpoint=http://localhost:40577®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2246460345/001/store'1952 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11953=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1954=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1955=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1956=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1957=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1958=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1959=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1960=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1961=== CONT TestClientErrorHandling/InvalidAuthToken1962--- PASS: TestClientCADerivations (0.82s)1963=== CONT TestClientErrorHandling/ServerNotAvailable19642026/10/14 16:46:50 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1965--- PASS: TestReadProxyNarinfo (0.47s)1966=== CONT TestCacheConfigHandler/full_config,_no_issuer1967=== CONT TestCacheConfigHandler/no_signing_keys1968=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1969=== CONT TestCacheConfigHandler/no_cache_url_configured1970--- PASS: TestCacheConfigHandler (0.00s)1971 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1972 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1973 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1974 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1975=== CONT TestGCEndsOnShutdown/before_the_run19762026/10/14 16:46:50 INFO Aborted multipart uploads count=0 kept=019772026/10/14 16:46:50 WARN Force mode enabled - objects will be deleted immediately without grace period19782026/10/14 16:46:50 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=01979--- PASS: TestGetExistingObjectsLocksRows (0.44s)1980=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19812026/10/14 16:46:50 INFO Vacuumed table table=pending_closures19822026/10/14 16:46:50 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/present19832026/10/14 16:46:50 INFO Vacuumed table table=pending_objects19842026/10/14 16:46:50 INFO Vacuumed table table=multipart_uploads19852026/10/14 16:46:50 INFO Vacuumed table table=closures19862026/10/14 16:46:50 INFO Vacuumed table table=objects1987--- PASS: TestSweepRechecksPendingAfterLocking (0.48s)1988=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19892026/10/14 16:46:50 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19902026/10/14 16:46:50 WARN mTLS auth: bound subjects configured but subject DN unavailable19912026/10/14 16:46:50 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1992--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.45s)1993=== CONT TestService_RequireScope_OIDC/builder_may_write1994=== CONT TestService_RequireScope_OIDC/writer_implies_read1995=== CONT TestService_RequireScope_OIDC/reader_may_read1996=== CONT TestService_RequireScope_OIDC/static_token_may_write1997=== CONT TestService_RequireScope_OIDC/static_token_may_admin1998=== CONT TestService_RequireScope_OIDC/reader_may_not_write1999=== CONT TestService_RequireScope_OIDC/ops_may_not_write2000=== CONT TestService_RequireScope_OIDC/ops_may_admin2001=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2002=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2003=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20042026/10/14 16:46:50 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]2005=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2006=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2007=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2008=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2009--- PASS: TestService_RequireScope_OIDC (0.57s)2010 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2011 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2012 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2013 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2014 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2015 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2016 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2017 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2018 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2019 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2020 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2021 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2022 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2023 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2024=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20252026/10/14 16:46:50 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]2026=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2027=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20282026/10/14 16:46:50 WARN Authentication failed token_preview=eyJhbGciOi...0The-IefSw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2029--- PASS: TestService_AuthMiddleware_OIDC (0.31s)2030 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2031 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2032 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2033 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2034--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.45s)20352026/10/14 16:46:50 INFO Received uploads request method=POST path=/api/pending_closures20362026/10/14 16:46:50 WARN Request failed, retrying attempt=2 backoff=190.164253ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20372026/10/14 16:46:50 INFO Received uploads request method=POST path=/api/pending_closures20382026/10/14 16:46:50 INFO Aborted multipart uploads count=0 kept=020392026/10/14 16:46:50 WARN Force mode enabled - objects will be deleted immediately without grace period20402026/10/14 16:46:50 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=020412026/10/14 16:46:50 INFO Vacuumed table table=pending_closures20422026/10/14 16:46:50 INFO Vacuumed table table=pending_objects20432026/10/14 16:46:50 INFO Vacuumed table table=multipart_uploads20442026/10/14 16:46:50 INFO Vacuumed table table=closures20452026/10/14 16:46:50 INFO Vacuumed table table=objects20462026/10/14 16:46:50 INFO Received uploads request method=POST path=/api/pending_closures20472026/10/14 16:46:50 INFO Aborted multipart uploads count=0 kept=020482026/10/14 16:46:50 WARN Force mode enabled - objects will be deleted immediately without grace period20492026/10/14 16:46:50 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=020502026/10/14 16:46:50 INFO Vacuumed table table=pending_closures20512026/10/14 16:46:50 INFO Vacuumed table table=pending_objects20522026/10/14 16:46:50 INFO Vacuumed table table=multipart_uploads20532026/10/14 16:46:50 INFO Vacuumed table table=closures20542026/10/14 16:46:50 INFO Vacuumed table table=objects2055--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2056 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.51s)2057 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.50s)2058--- PASS: TestDeleteClosuresRacingPins (1.64s)20592026/10/14 16:46:50 INFO Aborted multipart uploads count=0 kept=020602026/10/14 16:46:50 WARN Request failed, retrying attempt=3 backoff=390.055478ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20612026/10/14 16:46:50 WARN Force mode enabled - objects will be deleted immediately without grace period20622026/10/14 16:46:50 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20632026/10/14 16:46:50 INFO Aborted multipart uploads count=0 kept=020642026/10/14 16:46:50 WARN Force mode enabled - objects will be deleted immediately without grace period20652026/10/14 16:46:50 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:40577/bucket100/?delete=\": context canceled"2066--- PASS: TestGCEndsOnShutdown (0.00s)2067 --- PASS: TestGCEndsOnShutdown/before_the_run (0.30s)2068 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.31s)2069 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.31s)2070--- PASS: TestPushWaitsForSweepHoldingRow (0.83s)20712026/10/14 16:46:50 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2072--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)2073 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2074 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.07s)2075 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.73s)20762026/10/14 16:46:50 INFO lead: released remote=192.0.2.1:12342077--- PASS: TestLeadElectsOneAndHandsOver (2.95s)2078=== NAME TestOrphanedObjectsGCStressTest2079 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2080 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion20812026/10/14 16:46:50 WARN Request failed, retrying attempt=4 backoff=788.698173ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2082--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2083 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.88s)2084 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.95s)2085--- PASS: TestPendingClosureWriteTimeout (0.09s)2086 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2087 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2088 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2089 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.27s)2090=== NAME TestOrphanedObjectsGCStressTest2091 orphaned_objects_gc_test.go:503: Stress test completed successfully:2092 orphaned_objects_gc_test.go:504: - Active objects preserved: 202093 orphaned_objects_gc_test.go:505: - Objects deleted: 2102094 orphaned_objects_gc_test.go:506: - Total GC'd: 2102095--- PASS: TestOrphanedObjectsGCStressTest (2.85s)20962026/10/14 16:46:51 WARN Request failed, retrying attempt=5 backoff=1.62719554s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20972026/10/14 16:46:51 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020982026/10/14 16:46:51 INFO Received create pin request method=POST path=/api/pins/myapp20992026/10/14 16:46:51 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2059348664/001/store/hd2z9b2m9ragzymq8rn6nnhf5d84dp6j-pinned-file.txt narinfo_key=hd2z9b2m9ragzymq8rn6nnhf5d84dp6j.narinfo21002026/10/14 16:46:51 INFO Starting cleanup of old closures method=DELETE path=/api/closures21012026/10/14 16:46:51 INFO Garbage collection started21022026/10/14 16:46:51 INFO Aborted multipart uploads count=0 kept=021032026/10/14 16:46:51 WARN Force mode enabled - objects will be deleted immediately without grace period21042026/10/14 16:46:51 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=021052026/10/14 16:46:51 INFO Vacuumed table table=pending_closures21062026/10/14 16:46:51 INFO Vacuumed table table=pending_objects21072026/10/14 16:46:51 INFO Vacuumed table table=multipart_uploads21082026/10/14 16:46:51 INFO Vacuumed table table=closures21092026/10/14 16:46:51 INFO Vacuumed table table=objects21102026/10/14 16:46:51 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02111=== NAME TestClientIntegration2112 client_integration_test.go:323: Objects in database after GC:2113 client_integration_test.go:323: Successfully deleted all objects with GC --force2114--- PASS: TestClientIntegration (2.59s)21152026/10/14 16:46:52 WARN Rate limiter enabled after throttle name=s3-test rate=521162026/10/14 16:46:52 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2117=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2118 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102119 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002120--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.02s)2121--- PASS: TestConnectWaitsForAPeerMigration (5.15s)21222026/10/14 16:46:53 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-config21232026/10/14 16:46:53 WARN Request failed, retrying attempt=2 backoff=205.877843ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2124--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.73s)21252026/10/14 16:46:53 WARN Request failed, retrying attempt=3 backoff=367.870981ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2126=== NAME TestPinProtectsFromGC2127 client_integration_test.go:840: Pin successfully protected closure from garbage collection2128--- PASS: TestPinProtectsFromGC (4.74s)21292026/10/14 16:46:53 WARN Request failed, retrying attempt=4 backoff=764.284784ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21302026/10/14 16:46:54 WARN Request failed, retrying attempt=5 backoff=1.500489418s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21312026/10/14 16:46:55 INFO Aborted multipart uploads count=1 kept=021322026/10/14 16:46:55 INFO Received cleanup request method=DELETE path=/api/pending_closures21332026/10/14 16:46:55 INFO Aborted multipart uploads count=1 kept=02134--- PASS: TestPendingCleanupUsesOneCutoff (6.56s)21352026/10/14 16:46:56 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"21362026/10/14 16:46:56 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-config21372026/10/14 16:46:56 WARN Request failed, retrying attempt=2 backoff=215.568495ms 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:46:56 WARN Request failed, retrying attempt=3 backoff=381.657279ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21392026/10/14 16:46:56 WARN Request failed, retrying attempt=4 backoff=763.074405ms 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:46:57 WARN Request failed, retrying attempt=5 backoff=1.564191526s 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:46:59 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_closures21422026/10/14 16:46:59 WARN Request failed, retrying attempt=2 backoff=204.867985ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21432026/10/14 16:46:59 WARN Request failed, retrying attempt=3 backoff=430.632452ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21442026/10/14 16:46:59 WARN Request failed, retrying attempt=4 backoff=770.490528ms 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:47:00 WARN Request failed, retrying attempt=5 backoff=1.660914763s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2146--- PASS: TestClientErrorHandling (0.00s)2147 --- PASS: TestClientErrorHandling/InvalidStorePath (0.36s)2148 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.42s)2149 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.38s)2150PASS21512026-10-14 16:47:02.786 UTC [128] LOG: received smart shutdown request21522026-10-14 16:47:02.792 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 121532026-10-14 16:47:02.797 UTC [133] LOG: shutting down21542026-10-14 16:47:02.798 UTC [133] LOG: checkpoint starting: shutdown immediate21552026-10-14 16:47:05.204 UTC [133] LOG: checkpoint complete: wrote 10866 buffers (66.3%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.234 s, sync=2.113 s, total=2.407 s; sync files=34045, longest=0.009 s, average=0.001 s; distance=531583 kB, estimate=531583 kB; lsn=0/21E85A00, redo lsn=0/21E85A0021562026-10-14 16:47:05.283 UTC [128] LOG: database system is shut down2157Running OIDC tests...2158=== RUN TestAudienceForIssuer2159=== PAUSE TestAudienceForIssuer2160=== RUN TestGlobMatch2161=== PAUSE TestGlobMatch2162=== RUN TestValidateToken_ValidToken2163=== PAUSE TestValidateToken_ValidToken2164=== RUN TestValidateToken_WrongAudience2165=== PAUSE TestValidateToken_WrongAudience2166=== RUN TestValidateToken_Expired2167=== PAUSE TestValidateToken_Expired2168=== RUN TestValidateToken_BoundClaimsMismatch2169=== PAUSE TestValidateToken_BoundClaimsMismatch2170=== RUN TestValidateToken_BoundSubjectMismatch2171=== PAUSE TestValidateToken_BoundSubjectMismatch2172=== RUN TestValidateToken_MultipleProviders2173=== PAUSE TestValidateToken_MultipleProviders2174=== RUN TestValidateToken_NoMatchingProvider2175=== PAUSE TestValidateToken_NoMatchingProvider2176=== RUN TestValidateToken_KubernetesServiceAccount2177=== PAUSE TestValidateToken_KubernetesServiceAccount2178=== RUN TestNewValidator_KubernetesRequiresCA2179=== PAUSE TestNewValidator_KubernetesRequiresCA2180=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2181=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2182=== RUN TestPins_ReservedForMatchingRule2183=== PAUSE TestPins_ReservedForMatchingRule2184=== RUN TestPins_TopLevelShorthand2185=== PAUSE TestPins_TopLevelShorthand2186=== RUN TestPins_ConfigValidation2187=== PAUSE TestPins_ConfigValidation2188=== RUN TestScopes_LegacyProviderDefaultsToWrite2189=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2190=== RUN TestScopes_Rules2191=== PAUSE TestScopes_Rules2192=== RUN TestScopes_ConfigValidation2193=== PAUSE TestScopes_ConfigValidation2194=== CONT TestAudienceForIssuer2195=== CONT TestValidateToken_KubernetesServiceAccount2196--- PASS: TestAudienceForIssuer (0.00s)2197=== CONT TestValidateToken_NoMatchingProvider2198=== CONT TestValidateToken_MultipleProviders2199=== CONT TestValidateToken_BoundSubjectMismatch2200=== CONT TestValidateToken_BoundClaimsMismatch2201=== CONT TestValidateToken_Expired2202=== CONT TestValidateToken_WrongAudience2203=== CONT TestValidateToken_ValidToken2204=== CONT TestGlobMatch2205=== RUN TestGlobMatch/foo_foo2206=== PAUSE TestGlobMatch/foo_foo2207=== RUN TestGlobMatch/foo_bar2208=== PAUSE TestGlobMatch/foo_bar2209=== RUN TestGlobMatch/*_2210=== PAUSE TestGlobMatch/*_2211=== RUN TestGlobMatch/*_anything2212=== CONT TestScopes_Rules2213=== CONT TestScopes_ConfigValidation2214=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2215=== CONT TestScopes_LegacyProviderDefaultsToWrite2216=== CONT TestPins_TopLevelShorthand2217=== CONT TestNewValidator_KubernetesRequiresCA2218=== CONT TestPins_ConfigValidation2219=== CONT TestPins_ReservedForMatchingRule2220=== PAUSE TestGlobMatch/*_anything2221=== RUN TestGlobMatch/foo*_foo2222=== PAUSE TestGlobMatch/foo*_foo2223=== RUN TestGlobMatch/foo*_foobar2224=== PAUSE TestGlobMatch/foo*_foobar2225=== RUN TestGlobMatch/foo*_bar2226=== PAUSE TestGlobMatch/foo*_bar2227=== RUN TestGlobMatch/*bar_bar2228=== PAUSE TestGlobMatch/*bar_bar2229=== RUN TestGlobMatch/*bar_foobar2230=== PAUSE TestGlobMatch/*bar_foobar2231=== RUN TestGlobMatch/*bar_foo2232=== PAUSE TestGlobMatch/*bar_foo2233=== RUN TestGlobMatch/foo*bar_foobar2234=== PAUSE TestGlobMatch/foo*bar_foobar2235=== RUN TestGlobMatch/foo*bar_foo123bar2236=== PAUSE TestGlobMatch/foo*bar_foo123bar2237=== RUN TestGlobMatch/foo*bar_foobarbaz2238=== PAUSE TestGlobMatch/foo*bar_foobarbaz2239=== RUN TestGlobMatch/*/*_foo/bar2240=== PAUSE TestGlobMatch/*/*_foo/bar2241=== RUN TestGlobMatch/*/*_foo2242=== PAUSE TestGlobMatch/*/*_foo2243=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2244=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2245=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02246=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02247=== RUN TestGlobMatch/refs/*/main_refs/heads/main2248=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2249=== RUN TestGlobMatch/fo?_foo2250=== PAUSE TestGlobMatch/fo?_foo2251=== RUN TestGlobMatch/fo?_fo2252=== PAUSE TestGlobMatch/fo?_fo2253=== RUN TestGlobMatch/fo?_fooo2254=== PAUSE TestGlobMatch/fo?_fooo2255=== RUN TestGlobMatch/?oo_foo2256=== PAUSE TestGlobMatch/?oo_foo2257=== RUN TestGlobMatch/?oo_boo2258=== PAUSE TestGlobMatch/?oo_boo2259=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2260=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2261=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2262=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2263=== CONT TestGlobMatch/foo_foo2264=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2265=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2266=== CONT TestGlobMatch/?oo_boo2267=== CONT TestGlobMatch/?oo_foo2268=== CONT TestGlobMatch/fo?_fooo2269=== CONT TestGlobMatch/fo?_fo2270=== CONT TestGlobMatch/fo?_foo2271=== CONT TestGlobMatch/refs/*/main_refs/heads/main2272=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02273=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2274=== CONT TestGlobMatch/*/*_foo2275=== CONT TestGlobMatch/*/*_foo/bar2276=== CONT TestGlobMatch/foo*bar_foobarbaz2277=== CONT TestGlobMatch/foo*bar_foo123bar2278=== CONT TestGlobMatch/foo*bar_foobar2279=== CONT TestGlobMatch/*bar_foo2280=== CONT TestGlobMatch/*bar_foobar2281=== CONT TestGlobMatch/*bar_bar2282=== CONT TestGlobMatch/foo*_bar2283=== CONT TestGlobMatch/foo*_foobar2284=== CONT TestGlobMatch/foo*_foo2285=== CONT TestGlobMatch/*_anything2286=== CONT TestGlobMatch/*_2287=== CONT TestGlobMatch/foo_bar2288--- PASS: TestGlobMatch (0.00s)2289 --- PASS: TestGlobMatch/foo_foo (0.00s)2290 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2291 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2292 --- PASS: TestGlobMatch/?oo_boo (0.00s)2293 --- PASS: TestGlobMatch/?oo_foo (0.00s)2294 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2295 --- PASS: TestGlobMatch/fo?_fo (0.00s)2296 --- PASS: TestGlobMatch/fo?_foo (0.00s)2297 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2298 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2299 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2300 --- PASS: TestGlobMatch/*/*_foo (0.00s)2301 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2302 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2303 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2304 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2305 --- PASS: TestGlobMatch/*bar_foo (0.00s)2306 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2307 --- PASS: TestGlobMatch/*bar_bar (0.00s)2308 --- PASS: TestGlobMatch/foo*_bar (0.00s)2309 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2310 --- PASS: TestGlobMatch/foo*_foo (0.00s)2311 --- PASS: TestGlobMatch/*_anything (0.00s)2312 --- PASS: TestGlobMatch/*_ (0.00s)2313 --- PASS: TestGlobMatch/foo_bar (0.00s)2314--- PASS: TestPins_ConfigValidation (0.00s)2315--- PASS: TestScopes_ConfigValidation (0.01s)23162026/10/14 16:47:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37651/oidc2317--- PASS: TestValidateToken_WrongAudience (0.02s)23182026/10/14 16:47:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40077/oidc23192026/10/14 16:47:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45467/oidc2320--- PASS: TestValidateToken_ValidToken (0.04s)23212026/10/14 16:47:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33117/oidc2322--- PASS: TestValidateToken_BoundSubjectMismatch (0.05s)2323--- PASS: TestScopes_Rules (0.04s)23242026/10/14 16:47:07 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323252026/10/14 16:47:07 http: TLS handshake error from 127.0.0.1:57566: remote error: tls: bad certificate2326--- PASS: TestNewValidator_KubernetesRequiresCA (0.06s)23272026/10/14 16:47:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36935/oidc2328--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.06s)2329--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.05s)23302026/10/14 16:47:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40763/oidc2331--- PASS: TestPins_ReservedForMatchingRule (0.07s)23322026/10/14 16:47:07 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:3633323332026/10/14 16:47:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46463/oidc2334--- PASS: TestValidateToken_BoundClaimsMismatch (0.08s)2335--- PASS: TestValidateToken_KubernetesServiceAccount (0.08s)23362026/10/14 16:47:07 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:39375/oidc2337--- PASS: TestValidateToken_NoMatchingProvider (0.09s)23382026/10/14 16:47:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46615/oidc2339--- PASS: TestPins_TopLevelShorthand (0.08s)23402026/10/14 16:47:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:46585/oidc2341--- PASS: TestValidateToken_Expired (0.11s)23422026/10/14 16:47:07 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:36335/oidc23432026/10/14 16:47:07 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:46589/oidc2344--- PASS: TestValidateToken_MultipleProviders (0.23s)2345PASS2346Running hook tests...2347=== RUN TestSendPathsEmpty2348=== PAUSE TestSendPathsEmpty2349=== RUN TestQueueEnqueueAndFetch2350=== PAUSE TestQueueEnqueueAndFetch2351=== RUN TestQueueDeduplication2352=== PAUSE TestQueueDeduplication2353=== RUN TestQueueRemove2354=== PAUSE TestQueueRemove2355=== RUN TestQueueFetchBatchLimit2356=== PAUSE TestQueueFetchBatchLimit2357=== RUN TestQueueRetryMovesToBack2358=== PAUSE TestQueueRetryMovesToBack2359=== RUN TestQueueFetchRemoveLifecycle2360=== PAUSE TestQueueFetchRemoveLifecycle2361=== RUN TestQueueConcurrentWriters2362=== PAUSE TestQueueConcurrentWriters2363=== RUN TestQueueRemoveLargeClosure2364=== PAUSE TestQueueRemoveLargeClosure2365=== RUN TestServerClientIntegration2366--- PASS: TestServerClientIntegration (0.00s)2367=== RUN TestServerQueueError23682026/10/14 16:47:07 ERROR Failed to queue paths error="permission denied" count=12369--- PASS: TestServerQueueError (0.00s)2370=== RUN TestGetListenerSocketActivation2371 server_test.go:219: === RUN TestGetListenerSocketActivation2372 --- PASS: TestGetListenerSocketActivation (0.00s)2373 PASS2374 2375--- PASS: TestGetListenerSocketActivation (0.01s)2376=== RUN TestDrainIsolatesPoisonPath2377=== PAUSE TestDrainIsolatesPoisonPath2378=== RUN TestRunNotBlockedByPoisonHead2379=== PAUSE TestRunNotBlockedByPoisonHead2380=== RUN TestDrainGivesUpWhenServerDown2381=== PAUSE TestDrainGivesUpWhenServerDown2382=== RUN TestFailedPathPrunedByLaterClosure2383=== PAUSE TestFailedPathPrunedByLaterClosure2384=== RUN TestWorkerUploadsAndRemoves2385=== PAUSE TestWorkerUploadsAndRemoves2386=== RUN TestWorkerSkipsGCdPaths2387=== PAUSE TestWorkerSkipsGCdPaths2388=== RUN TestWorkerPrunesClosureDeps2389=== PAUSE TestWorkerPrunesClosureDeps2390=== RUN TestDrainTimeout2391=== PAUSE TestDrainTimeout2392=== CONT TestSendPathsEmpty2393=== CONT TestRunNotBlockedByPoisonHead2394=== CONT TestDrainIsolatesPoisonPath2395=== CONT TestDrainTimeout2396=== CONT TestFailedPathPrunedByLaterClosure2397=== CONT TestDrainGivesUpWhenServerDown2398=== CONT TestWorkerUploadsAndRemoves2399--- PASS: TestSendPathsEmpty (0.00s)2400=== CONT TestQueueRemoveLargeClosure2401=== CONT TestWorkerPrunesClosureDeps2402=== CONT TestQueueConcurrentWriters2403=== CONT TestQueueFetchRemoveLifecycle2404=== CONT TestQueueRetryMovesToBack2405=== CONT TestWorkerSkipsGCdPaths2406=== CONT TestQueueDeduplication2407=== CONT TestQueueEnqueueAndFetch2408=== CONT TestQueueFetchBatchLimit2409=== CONT TestQueueRemove24102026/10/14 16:47:07 INFO Uploading batch count=424112026/10/14 16:47:07 ERROR Upload failed error="upload failed" count=424122026/10/14 16:47:07 INFO Uploading batch count=224132026/10/14 16:47:07 INFO Upload queue status pending=224142026/10/14 16:47:07 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3658279850/002/bbb2415--- PASS: TestQueueDeduplication (0.01s)24162026/10/14 16:47:07 INFO Uploading batch count=124172026/10/14 16:47:07 INFO Uploading batch count=224182026/10/14 16:47:07 INFO Upload queue status pending=224192026/10/14 16:47:07 INFO Upload queue status pending=324202026/10/14 16:47:07 ERROR Upload failed error="upload failed" count=124212026/10/14 16:47:07 INFO Uploading batch count=224222026/10/14 16:47:07 ERROR Upload failed error="upload failed" count=224232026/10/14 16:47:07 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2274855835/002/a2424--- PASS: TestQueueEnqueueAndFetch (0.01s)24252026/10/14 16:47:07 INFO Upload queue status pending=224262026/10/14 16:47:07 INFO Uploading batch count=124272026/10/14 16:47:07 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1884262313/002/nonexistent24282026/10/14 16:47:07 ERROR Upload failed error="upload failed" count=12429--- PASS: TestQueueFetchRemoveLifecycle (0.01s)24302026/10/14 16:47:07 INFO Uploading batch count=12431--- PASS: TestQueueFetchBatchLimit (0.01s)2432--- PASS: TestQueueRetryMovesToBack (0.01s)24332026/10/14 16:47:07 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2274855835/002/b24342026/10/14 16:47:07 INFO Uploading batch count=124352026/10/14 16:47:07 INFO Uploading batch count=124362026/10/14 16:47:07 ERROR Upload failed error="upload failed" count=124372026/10/14 16:47:07 INFO Uploading batch count=12438--- PASS: TestQueueRemove (0.01s)24392026/10/14 16:47:07 INFO Uploading batch count=224402026/10/14 16:47:07 ERROR Upload failed error="upload failed" count=224412026/10/14 16:47:07 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2274855835/002/c24422026/10/14 16:47:07 INFO Uploading batch count=124432026/10/14 16:47:07 INFO Uploading batch count=124442026/10/14 16:47:07 ERROR Upload failed error="upload failed" count=124452026/10/14 16:47:07 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2274855835/002/d24462026/10/14 16:47:07 INFO Uploading batch count=124472026/10/14 16:47:07 ERROR Upload failed error="upload failed" count=124482026/10/14 16:47:07 INFO Uploading batch count=224492026/10/14 16:47:07 ERROR Upload failed error="upload failed" count=224502026/10/14 16:47:07 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2274855835/002/e24512026/10/14 16:47:07 ERROR Drain finished with paths left in queue remaining=124522026/10/14 16:47:07 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown2274855835/002/f2453--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24542026/10/14 16:47:07 ERROR Drain finished with paths left in queue remaining=102455--- PASS: TestDrainIsolatesPoisonPath (0.02s)2456--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2457--- PASS: TestWorkerPrunesClosureDeps (0.03s)2458--- PASS: TestWorkerUploadsAndRemoves (0.03s)2459--- PASS: TestWorkerSkipsGCdPaths (0.03s)2460--- PASS: TestQueueRemoveLargeClosure (0.05s)24612026/10/14 16:47:08 ERROR Upload failed error="context deadline exceeded" count=224622026/10/14 16:47:08 ERROR Drain finished with paths left in queue remaining=42463--- PASS: TestDrainTimeout (0.21s)2464--- PASS: TestQueueConcurrentWriters (0.37s)24652026/10/14 16:47:08 INFO Uploading batch count=124662026/10/14 16:47:08 INFO Uploading batch count=124672026/10/14 16:47:08 INFO Uploading batch count=124682026/10/14 16:47:08 ERROR Upload failed error="upload failed" count=124692026/10/14 16:47:08 INFO Uploading batch count=124702026/10/14 16:47:08 ERROR Upload failed error="upload failed" count=124712026/10/14 16:47:08 INFO Uploading batch count=124722026/10/14 16:47:08 ERROR Upload failed error="upload failed" count=124732026/10/14 16:47:08 INFO Uploading batch count=124742026/10/14 16:47:08 ERROR Upload failed error="upload failed" count=124752026/10/14 16:47:08 ERROR Drain finished with paths left in queue remaining=12476--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2477PASS2478Running signing tests...2479=== RUN TestExternalSigner2480=== PAUSE TestExternalSigner2481=== RUN TestExternalSignerWrongPublicKey2482=== PAUSE TestExternalSignerWrongPublicKey2483=== RUN TestExternalSignerErrors2484=== PAUSE TestExternalSignerErrors2485=== RUN TestExternalSignerRestartsAfterCrash2486=== PAUSE TestExternalSignerRestartsAfterCrash2487=== RUN TestExternalSignerProgramErrorKeepsProcess2488=== PAUSE TestExternalSignerProgramErrorKeepsProcess2489=== RUN TestExternalSignerClose2490=== PAUSE TestExternalSignerClose2491=== RUN TestExternalSignerRejectsInvalidPublicKey2492=== PAUSE TestExternalSignerRejectsInvalidPublicKey2493=== RUN TestExternalSignerCancellation2494=== PAUSE TestExternalSignerCancellation2495=== RUN TestGenerateFingerprint2496=== PAUSE TestGenerateFingerprint2497=== RUN TestParseSigningKey2498=== PAUSE TestParseSigningKey2499=== RUN TestSign2500=== PAUSE TestSign2501=== RUN TestSignBatch2502=== PAUSE TestSignBatch2503=== RUN TestNilKeyPublicKey2504=== PAUSE TestNilKeyPublicKey2505=== RUN TestSignErrors2506=== PAUSE TestSignErrors2507=== CONT TestExternalSigner2508=== CONT TestSignBatch2509=== CONT TestExternalSignerProgramErrorKeepsProcess2510=== CONT TestExternalSignerCancellation2511=== CONT TestGenerateFingerprint2512=== RUN TestGenerateFingerprint/basic_with_references2513=== CONT TestExternalSignerErrors2514=== CONT TestExternalSignerRestartsAfterCrash2515=== CONT TestSign2516=== CONT TestExternalSignerRejectsInvalidPublicKey2517=== CONT TestExternalSignerWrongPublicKey2518=== CONT TestExternalSignerClose2519=== CONT TestSignErrors2520=== CONT TestNilKeyPublicKey2521=== CONT TestParseSigningKey2522=== RUN TestParseSigningKey/valid_32-byte_key2523=== PAUSE TestGenerateFingerprint/basic_with_references2524=== RUN TestGenerateFingerprint/no_references2525=== PAUSE TestGenerateFingerprint/no_references2526=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2527--- PASS: TestSign (0.00s)2528=== PAUSE TestParseSigningKey/valid_32-byte_key2529=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2530=== RUN TestExternalSignerRejectsInvalidPublicKey/#002531=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002532=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2533=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2534=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2535=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2536=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2537=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2538=== RUN TestExternalSignerErrors/null2539=== PAUSE TestExternalSignerErrors/null2540=== RUN TestExternalSignerErrors/wrong_signatures_shape2541=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2542=== RUN TestExternalSignerErrors/unrequested_key2543=== PAUSE TestExternalSignerErrors/unrequested_key2544=== RUN TestExternalSignerErrors/exit_at_startup2545=== PAUSE TestExternalSignerErrors/exit_at_startup2546=== RUN TestExternalSignerErrors/invalid_JSON2547=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2548--- PASS: TestSignBatch (0.00s)2549=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2550=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2551=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2552=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2553=== RUN TestSignErrors/nil_key2554=== RUN TestParseSigningKey/no_colon2555=== PAUSE TestSignErrors/nil_key2556=== RUN TestSignErrors/nil_narinfo2557=== PAUSE TestSignErrors/nil_narinfo2558=== RUN TestSignErrors/invalid_narinfo2559=== PAUSE TestSignErrors/invalid_narinfo2560=== RUN TestSignErrors/canceled2561=== PAUSE TestSignErrors/canceled2562=== CONT TestSignErrors/nil_key2563=== PAUSE TestParseSigningKey/no_colon2564=== RUN TestParseSigningKey/empty_name2565=== PAUSE TestParseSigningKey/empty_name2566--- PASS: TestNilKeyPublicKey (0.00s)2567=== RUN TestGenerateFingerprint/invalid_nar_hash_length2568=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2569=== RUN TestGenerateFingerprint/invalid_store_path_prefix2570=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2571=== PAUSE TestExternalSignerErrors/invalid_JSON2572=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2573=== CONT TestSignErrors/invalid_narinfo2574=== CONT TestSignErrors/canceled2575=== CONT TestSignErrors/nil_narinfo2576--- PASS: TestSignErrors (0.00s)2577 --- PASS: TestSignErrors/nil_key (0.00s)2578 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2579 --- PASS: TestSignErrors/canceled (0.00s)2580 --- PASS: TestSignErrors/nil_narinfo (0.00s)2581=== RUN TestParseSigningKey/invalid_base642582=== PAUSE TestParseSigningKey/invalid_base642583=== RUN TestParseSigningKey/wrong_length2584=== PAUSE TestParseSigningKey/wrong_length2585=== CONT TestExternalSignerRejectsInvalidPublicKey/#002586=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2587=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2588=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2589=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2590--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2591 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2592 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2593 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2594 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2595 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2596=== RUN TestGenerateFingerprint/invalid_reference_prefix2597=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2598=== CONT TestGenerateFingerprint/basic_with_references2599=== RUN TestExternalSignerErrors/missing_signature_name2600=== PAUSE TestExternalSignerErrors/missing_signature_name2601=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2602=== RUN TestExternalSignerErrors/wrong_signature_name2603=== CONT TestGenerateFingerprint/no_references2604=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2605=== CONT TestParseSigningKey/wrong_length2606=== CONT TestParseSigningKey/invalid_base642607=== CONT TestParseSigningKey/empty_name2608=== CONT TestParseSigningKey/no_colon2609=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2610=== CONT TestGenerateFingerprint/invalid_reference_prefix2611=== CONT TestGenerateFingerprint/invalid_store_path_prefix2612=== CONT TestGenerateFingerprint/invalid_nar_hash_length2613=== CONT TestParseSigningKey/valid_32-byte_key2614--- PASS: TestExternalSignerClose (0.00s)2615=== PAUSE TestExternalSignerErrors/wrong_signature_name2616--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2617=== RUN TestExternalSignerErrors/wrong_signature_length2618--- PASS: TestGenerateFingerprint (0.00s)2619 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2620 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2621 --- PASS: TestGenerateFingerprint/no_references (0.00s)2622 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2623 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2624 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2625 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2626--- PASS: TestParseSigningKey (0.00s)2627 --- PASS: TestParseSigningKey/wrong_length (0.00s)2628 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2629 --- PASS: TestParseSigningKey/empty_name (0.00s)2630 --- PASS: TestParseSigningKey/no_colon (0.00s)2631 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2632 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2633=== PAUSE TestExternalSignerErrors/wrong_signature_length2634=== RUN TestExternalSignerErrors/program_error2635=== PAUSE TestExternalSignerErrors/program_error2636=== RUN TestExternalSignerErrors/wrong_id2637--- PASS: TestExternalSignerWrongPublicKey (0.00s)2638=== PAUSE TestExternalSignerErrors/wrong_id2639=== RUN TestExternalSignerErrors/missing_signatures2640=== PAUSE TestExternalSignerErrors/missing_signatures2641=== RUN TestExternalSignerErrors/null_signatures2642=== PAUSE TestExternalSignerErrors/null_signatures2643=== RUN TestExternalSignerErrors/too_few_signatures2644=== PAUSE TestExternalSignerErrors/too_few_signatures2645=== RUN TestExternalSignerErrors/exit_on_request2646=== PAUSE TestExternalSignerErrors/exit_on_request2647=== RUN TestExternalSignerErrors/wrong_shape2648=== PAUSE TestExternalSignerErrors/wrong_shape2649=== RUN TestExternalSignerErrors/invalid_signature_base642650=== PAUSE TestExternalSignerErrors/invalid_signature_base642651=== CONT TestExternalSignerErrors/null2652=== CONT TestExternalSignerErrors/too_few_signatures2653=== CONT TestExternalSignerErrors/wrong_signatures_shape2654=== CONT TestExternalSignerErrors/null_signatures2655=== CONT TestExternalSignerErrors/invalid_signature_base642656=== CONT TestExternalSignerErrors/wrong_shape2657=== CONT TestExternalSignerErrors/exit_on_request2658=== CONT TestExternalSignerErrors/wrong_signature_name2659=== CONT TestExternalSignerErrors/missing_signatures2660=== CONT TestExternalSignerErrors/wrong_id2661=== CONT TestExternalSignerErrors/program_error2662=== CONT TestExternalSignerErrors/wrong_signature_length2663=== CONT TestExternalSignerErrors/missing_signature_name2664=== CONT TestExternalSignerErrors/unrequested_key2665=== CONT TestExternalSignerErrors/invalid_JSON2666=== CONT TestExternalSignerErrors/exit_at_startup2667--- PASS: TestExternalSigner (0.01s)2668--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2669--- PASS: TestExternalSignerErrors (0.00s)2670 --- PASS: TestExternalSignerErrors/null_signatures (0.00s)2671 --- PASS: TestExternalSignerErrors/null (0.00s)2672 --- PASS: TestExternalSignerErrors/too_few_signatures (0.00s)2673 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2674 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.00s)2675 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2676 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2677 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2678 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2679 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)2680 --- PASS: TestExternalSignerErrors/program_error (0.01s)2681 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2682 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2683 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)2684 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2685 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2686--- PASS: TestExternalSignerCancellation (0.02s)2687PASS2688Running OpenBao signer tests...2689=== RUN TestSign2690=== PAUSE TestSign2691=== RUN TestSignErrors2692=== PAUSE TestSignErrors2693=== RUN TestServe2694=== PAUSE TestServe2695=== RUN TestServeRejectsGarbage2696=== PAUSE TestServeRejectsGarbage2697=== CONT TestSign2698=== CONT TestSignErrors2699=== CONT TestServe2700=== CONT TestServeRejectsGarbage2701=== RUN TestSignErrors/invalid_json2702--- PASS: TestServe (0.00s)2703--- PASS: TestServeRejectsGarbage (0.00s)2704=== PAUSE TestSignErrors/invalid_json2705=== RUN TestSignErrors/no_prefix2706=== PAUSE TestSignErrors/no_prefix2707=== RUN TestSignErrors/invalid_base642708=== PAUSE TestSignErrors/invalid_base642709=== RUN TestSignErrors/http_error2710=== PAUSE TestSignErrors/http_error2711=== CONT TestSignErrors/invalid_json2712=== CONT TestSignErrors/invalid_base642713=== CONT TestSignErrors/http_error2714=== CONT TestSignErrors/no_prefix2715--- PASS: TestSign (0.00s)2716--- PASS: TestSignErrors (0.00s)2717 --- PASS: TestSignErrors/invalid_json (0.00s)2718 --- PASS: TestSignErrors/http_error (0.00s)2719 --- PASS: TestSignErrors/no_prefix (0.00s)2720 --- PASS: TestSignErrors/invalid_base64 (0.00s)2721PASS