niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #455
· raw
1tribuchet: building on mac022Running 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 TestUploadMultipart_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.16s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestScriptTokenEmptyToken117=== CONT TestSetClientTLSErrors118=== CONT TestScriptTokenScriptFails119=== CONT TestUploadMultipart_PartsInParallel120=== CONT TestDumpPathSingleFile121=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun122=== CONT TestRegisterUploadedObjectReusesConnections123=== CONT TestEncodeNixBase32WithRealHash124=== CONT TestFilterOversizedClosures125--- PASS: TestEncodeNixBase32WithRealHash (0.00s)126=== CONT TestCaseHackSuffix127=== CONT TestScriptTokenCachesUntilRefresh128=== CONT TestScriptTokenNoExpiryRerunsEveryCall129=== CONT TestFileTokenEmpty130=== CONT TestFileTokenMissing131=== CONT TestFileTokenReadsAndCaches132=== CONT TestStaticToken133=== CONT TestPathInfoHashCompatibility134=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess135=== CONT TestRateLimiterFeedback136=== CONT TestPathInfoCACompatibility137=== CONT TestParsePathInfoJSONMultiplePaths138=== CONT TestParsePathInfoJSON139=== CONT TestScriptTokenEmptyCommand140=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer141=== RUN TestFilterOversizedClosures/no_limit_keeps_everything1422026/11/01 17:55:40 INFO Garbage collection started143--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)144=== CONT TestEncodeNixBase32145=== RUN TestEncodeNixBase32/test_string_hash146=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)147--- PASS: TestScriptTokenScriptFails (0.02s)148--- PASS: TestStaticToken (0.00s)149=== RUN TestPathInfoCACompatibility/null_ca_field150=== PAUSE TestPathInfoCACompatibility/null_ca_field151=== RUN TestPathInfoCACompatibility/old_string_format_-_text152=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text153=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive154=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive155=== RUN TestParsePathInfoJSON/Nix_format156--- PASS: TestScriptTokenEmptyCommand (0.00s)157=== CONT TestStreamPushIsolatesFailures158=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything159=== PAUSE TestParsePathInfoJSON/Nix_format160=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped161=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths162=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths163=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths164=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths165=== RUN TestParsePathInfoJSON/Lix_format166=== PAUSE TestParsePathInfoJSON/Lix_format167=== RUN TestParsePathInfoJSON/empty_input168=== PAUSE TestParsePathInfoJSON/empty_input169=== RUN TestParsePathInfoJSON/whitespace_only170=== PAUSE TestParsePathInfoJSON/whitespace_only171=== RUN TestParsePathInfoJSON/invalid_JSON172=== RUN TestPathInfoCACompatibility/new_structured_format_-_text1732026/11/01 17:55:40 ERROR Upload failed error="bad path" count=3174=== CONT TestSetClientTLSDoesNotMutateDefaultTransport175=== RUN TestRateLimiterFeedback/429_enables_limiter176=== PAUSE TestRateLimiterFeedback/429_enables_limiter177=== RUN TestRateLimiterFeedback/503_enables_limiter178=== PAUSE TestRateLimiterFeedback/503_enables_limiter179=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter180=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter181=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter182=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter183=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)184=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon185=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon186=== CONT TestSetClientTLS187=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text188=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method189=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method190=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped191=== RUN TestFilterOversizedClosures/all_closures_skipped192=== PAUSE TestFilterOversizedClosures/all_closures_skipped193=== CONT TestClientSignaturesByStorePath194=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica195--- PASS: TestStreamPushIsolatesFailures (0.00s)196--- PASS: TestClientSignaturesByStorePath (0.00s)197=== CONT TestStreamPushReportsSkippedPaths198--- PASS: TestStreamPushReportsSkippedPaths (0.00s)199=== CONT TestStreamPushReportsSignatures200=== CONT TestStreamPushStopsWhenCanceled201--- PASS: TestStreamPushStopsWhenCanceled (0.00s)202=== CONT TestStreamPushRequestLine203=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI204=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI205=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512206=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha5122072026/11/01 17:55:40 ERROR Upload failed error=boom count=1208=== CONT TestStreamPushGivesUpOnDeadServer209--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)210--- PASS: TestFileTokenReadsAndCaches (0.00s)211=== CONT TestShellSplit212--- PASS: TestShellSplit (0.00s)213=== CONT TestStreamPushBatchesUnderLoad214=== CONT TestStreamPushReportsEveryPath215=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false216=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false217=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true218=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true219--- PASS: TestStreamPushReportsEveryPath (0.00s)220=== CONT TestDumpPathWriterError221=== CONT TestShellSplitErrors222--- PASS: TestShellSplitErrors (0.00s)223=== CONT TestScriptTokenBadJSON2242026/11/01 17:55:40 WARN Rate limiter enabled after throttle name=server-test rate=5225=== PAUSE TestParsePathInfoJSON/invalid_JSON226=== CONT TestConvertHashToNix32227=== RUN TestConvertHashToNix32/SRI_format_to_Nix32228=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32229=== RUN TestConvertHashToNix32/already_Nix32_format230=== PAUSE TestConvertHashToNix32/already_Nix32_format231=== RUN TestConvertHashToNix32/invalid_format232=== PAUSE TestConvertHashToNix32/invalid_format233=== CONT TestDumpPathMatchesNix2342026/11/01 17:55:40 ERROR Upload failed error="connection refused" count=202352026/11/01 17:55:40 ERROR Server seems unavailable, giving up on batch untried=17236--- PASS: TestStreamPushGivesUpOnDeadServer (0.01s)237=== CONT TestSupersededNARStillUploadsListing238=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry239=== RUN TestSetClientTLS/rejects_connection_without_client_cert240=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert241=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA242=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA243=== RUN TestSetClientTLS/preserves_debug_logging_transport244=== PAUSE TestSetClientTLS/preserves_debug_logging_transport245=== CONT TestUploadMultipart_SupersededByPeer246=== RUN TestUploadMultipart_SupersededByPeer/exists247=== PAUSE TestUploadMultipart_SupersededByPeer/exists248=== RUN TestUploadMultipart_SupersededByPeer/missing249=== PAUSE TestUploadMultipart_SupersededByPeer/missing250=== CONT TestUploadMultipart_FailedPartBufferNotReused251=== RUN TestSupersededNARStillUploadsListing/small_NAR252=== PAUSE TestSupersededNARStillUploadsListing/small_NAR253=== RUN TestSupersededNARStillUploadsListing/dump_cut_short254=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short255=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails256=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails257=== CONT TestPartSizeForNAR258=== RUN TestPartSizeForNAR/zero_stays_at_minimum259=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum260=== RUN TestPartSizeForNAR/small_stays_at_minimum261=== PAUSE TestPartSizeForNAR/small_stays_at_minimum262=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum263=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum264=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts265=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts266=== RUN TestPartSizeForNAR/1_TiB267=== PAUSE TestPartSizeForNAR/1_TiB268=== RUN TestPartSizeForNAR/5_TiB_S3_max_object269=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object270=== RUN TestPartSizeForNAR/capped_at_5_GiB271=== PAUSE TestPartSizeForNAR/capped_at_5_GiB272=== CONT TestRetryTimeoutOutlastsMaxRetries273=== PAUSE TestEncodeNixBase32/test_string_hash274=== CONT TestGetStorePathHash275=== RUN TestGetStorePathHash/valid_store_path276=== PAUSE TestGetStorePathHash/valid_store_path277=== RUN TestGetStorePathHash/basename_without_hyphen_should_error278=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error279=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error280=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error281=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error282=== RUN TestSetClientTLSErrors/missing_cert_file283=== RUN TestEncodeNixBase32/empty_input284=== PAUSE TestEncodeNixBase32/empty_input285=== CONT TestDoWithRetry_BodyReplayedViaGetBody286=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error287=== CONT TestDoWithRetry_FinalResponseBodyReadable288=== PAUSE TestSetClientTLSErrors/missing_cert_file289--- PASS: TestFileTokenMissing (0.05s)2902026/11/01 17:55:40 INFO Garbage collection started2912026/11/01 17:55:40 ERROR Upload failed error=boom count=1292=== CONT TestResolveStorePath293--- PASS: TestStreamPushReportsSignatures (0.04s)294=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths295=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths296=== CONT TestRateLimiterFeedback/429_enables_limiter297--- PASS: TestScriptTokenBadJSON (0.03s)298=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter299=== RUN TestSetClientTLSErrors/missing_key_file300=== PAUSE TestSetClientTLSErrors/missing_key_file301=== RUN TestSetClientTLSErrors/missing_ca_file302=== PAUSE TestSetClientTLSErrors/missing_ca_file303=== RUN TestSetClientTLSErrors/invalid_ca_file304=== PAUSE TestSetClientTLSErrors/invalid_ca_file305=== CONT TestRateLimiterFeedback/503_enables_limiter306--- PASS: TestDoServerRequestAttachesToken (0.07s)3072026/11/01 17:55:40 WARN Rate limiter enabled after throttle name=s3-test rate=53082026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55950309=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter310--- PASS: TestFileTokenEmpty (0.06s)311=== CONT TestPathInfoCACompatibility/null_ca_field312=== CONT TestFilterOversizedClosures/no_limit_keeps_everything313=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method314=== CONT TestPathInfoCACompatibility/new_structured_format_-_text315=== CONT TestPathInfoCACompatibility/old_string_format_-_text316--- PASS: TestResolveStorePath (0.00s)317--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)318 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)319 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)320=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive321--- PASS: TestPathInfoCACompatibility (0.00s)322 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)323 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)324 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)325 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)326 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)327=== CONT TestFilterOversizedClosures/all_closures_skipped328=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3292026/11/01 17:55:40 WARN Rate limiter enabled after throttle name=server-test rate=53302026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55961331=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)3322026/11/01 17:55:40 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=50333=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI334=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512335=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false3362026/11/01 17:55:40 WARN Rate limiter enabled after throttle name=server-test rate=53372026/11/01 17:55:40 WARN Rate limiter enabled after throttle name=server-test rate=53382026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:55986339=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon340--- PASS: TestPathInfoHashCompatibility (0.00s)341 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)342 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)343 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)344 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)345=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true3462026/11/01 17:55:40 WARN Rate limiter backed off name=server-test rate=5347=== CONT TestConvertHashToNix32/SRI_format_to_Nix323482026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:55961349=== CONT TestParsePathInfoJSON/Nix_format3502026/11/01 17:55:40 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=2000351--- PASS: TestFilterOversizedClosures (0.02s)352 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)353 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)354 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)3552026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55982356=== CONT TestParsePathInfoJSON/whitespace_only357=== CONT TestParsePathInfoJSON/invalid_JSON358=== CONT TestParsePathInfoJSON/empty_input359=== CONT TestParsePathInfoJSON/Lix_format360=== CONT TestSetClientTLS/rejects_connection_without_client_cert361=== CONT TestConvertHashToNix32/already_Nix32_format362=== CONT TestUploadMultipart_SupersededByPeer/exists363=== CONT TestConvertHashToNix32/invalid_format364--- PASS: TestParsePathInfoJSON (0.02s)365 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)366 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)367 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)368 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)369 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)370--- PASS: TestConvertHashToNix32 (0.00s)371 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)372 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)373 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)374=== CONT TestSetClientTLS/preserves_debug_logging_transport3752026/11/01 17:55:40 WARN Rate limiter backed off name=server-test rate=53762026/11/01 17:55:40 WARN Rate limiter backed off name=server-test rate=5377--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)378=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA379--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)380=== CONT TestUploadMultipart_SupersededByPeer/missing381--- PASS: TestStreamPushBatchesUnderLoad (0.00s)382 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)383 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)384=== CONT TestSupersededNARStillUploadsListing/small_NAR385=== CONT TestPartSizeForNAR/zero_stays_at_minimum386=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails387--- PASS: TestScriptTokenEmptyToken (0.07s)388=== CONT TestSupersededNARStillUploadsListing/dump_cut_short389--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.03s)390=== CONT TestPartSizeForNAR/capped_at_5_GiB391=== CONT TestPartSizeForNAR/5_TiB_S3_max_object392=== CONT TestPartSizeForNAR/1_TiB393=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts394=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum395=== CONT TestPartSizeForNAR/small_stays_at_minimum396--- PASS: TestPartSizeForNAR (0.00s)397 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)398 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)399 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)400 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)401 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)402 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)403 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)404=== CONT TestEncodeNixBase32/test_string_hash405=== CONT TestEncodeNixBase32/empty_input406--- PASS: TestEncodeNixBase32 (0.02s)407 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)408 --- PASS: TestEncodeNixBase32/empty_input (0.00s)409=== CONT TestGetStorePathHash/valid_store_path410=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error411=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error412=== CONT TestGetStorePathHash/basename_without_hyphen_should_error413--- PASS: TestGetStorePathHash (0.00s)414 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)415 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)416 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)417 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)418=== CONT TestSetClientTLSErrors/missing_cert_file419=== CONT TestSetClientTLSErrors/missing_ca_file420=== CONT TestSetClientTLSErrors/invalid_ca_file4212026/11/01 17:55:40 INFO Uploading abc-hello (1.0GB)422=== CONT TestSetClientTLSErrors/missing_key_file4232026/11/01 17:55:40 INFO Uploading abc-hello (1.0GB)424--- PASS: TestCaseHackSuffix (0.08s)4252026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:559674262026/11/01 17:55:40 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=0427--- PASS: TestSetClientTLSErrors (0.08s)428 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)429 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)430 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)431 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)4322026/11/01 17:55:40 WARN Rate limiter enabled after throttle name=server-test rate=54332026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:559804342026/11/01 17:55:40 WARN Rate limiter backed off name=server-test rate=5435--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)436 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.02s)437 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.02s)438--- PASS: TestStreamPushRequestLine (0.06s)439--- PASS: TestRateLimiterFeedback (0.00s)440 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)441 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)442 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)443 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.02s)4442026/11/01 17:55:40 WARN Garbage collection finished on another replica. Its statistics are not available here445--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.06s)4462026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:559674472026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:55967448--- PASS: TestScriptTokenCachesUntilRefresh (0.09s)4492026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:559674502026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:559674512026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:559674522026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:559674532026/11/01 17:55:40 WARN Rate limiter enabled after throttle name=s3-test rate=54542026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:559674552026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:559674562026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:559674572026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:55967458--- PASS: TestRegisterUploadedObjectReusesConnections (0.10s)4592026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:559674602026/11/01 17:55:40 http: TLS handshake error from 127.0.0.1:55990: remote error: tls: bad certificate461--- PASS: TestSetClientTLS (0.02s)462 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.02s)463 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.02s)464 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.04s)4652026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:559674662026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:559674672026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:559674682026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:559674692026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:559674702026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:559674712026/11/01 17:55:40 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:55967472--- PASS: TestDumpPathSingleFile (0.11s)473--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.08s)474--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.13s)4752026/11/01 17:55:40 INFO Uploading abc-hello (1.0GB)476--- PASS: TestDumpPathWriterError (0.12s)4772026/11/01 17:55:40 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:55991/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:55991/part/24782026/11/01 17:55:40 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:55991/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:55991/part/34792026/11/01 17:55:40 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"480--- PASS: TestDumpPathMatchesNix (0.14s)481--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.61s)482--- PASS: TestSupersededNARStillUploadsListing (0.00s)483 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.02s)484 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.02s)485 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.59s)486--- PASS: TestUploadMultipart_PartsInParallel (0.69s)4872026/11/01 17:55:41 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55903/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55903/api/uploads/complete4882026/11/01 17:55:41 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4892026/11/01 17:55:41 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55903/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55903/api/uploads/complete4902026/11/01 17:55:41 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4912026/11/01 17:55:41 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55903/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55903/api/uploads/complete4922026/11/01 17:55:41 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"493--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)494--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.02s)495PASS496Running server tests...497The files belonging to this database system will be owned by user "_tribuchetbld8".498This user must also own the server process.499500The database cluster will be initialized with locale "C".501The default database encoding has accordingly been set to "SQL_ASCII".502The default text search configuration will be set to "english".503504Data page checksums are enabled.505506creating directory /private/var/tb/8/scratch/90a332d44a448eb6/build/postgres367480327/data ... ok507creating subdirectories ... ok508selecting dynamic shared memory implementation ... posix509selecting default "max_connections" ... 100510selecting default "shared_buffers" ... 128MB511selecting default time zone ... UTC512creating configuration files ... ok513running bootstrap script ... ok514performing post-bootstrap initialization ... ok515syncing data to disk ... ok516517initdb: warning: enabling "trust" authentication for local connections518initdb: 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.519520Success. You can now start the database server using:521522 pg_ctl -D /private/var/tb/8/scratch/90a332d44a448eb6/build/postgres367480327/data -l logfile start523524/private/var/tb/8/scratch/90a332d44a448eb6/build/postgres367480327:5432 - no response5252026-11-01 17:55:41.983 UTC [37028] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5262026-11-01 17:55:41.983 UTC [37028] LOG: listening on Unix socket "/private/var/tb/8/scratch/90a332d44a448eb6/build/postgres367480327/.s.PGSQL.5432"5272026-11-01 17:55:41.986 UTC [37035] LOG: database system was shut down at 2026-11-01 17:55:41 UTC5282026-11-01 17:55:41.987 UTC [37028] LOG: database system is ready to accept connections529/private/var/tb/8/scratch/90a332d44a448eb6/build/postgres367480327:5432 - accepting connections530{"timestamp":"2026-11-01T17:55:42.226725Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"f4ac5f7d-3991-4b9c-b0ae-b7b8585b8918","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":10,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}531{"timestamp":"2026-11-01T17:55:42.334497Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"0e5a44b5-2012-45c8-86e8-f3e5a284eb5b","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":502,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}532=== RUN TestService_AuthMiddleware533=== PAUSE TestService_AuthMiddleware534=== RUN TestService_AuthMiddleware_MTLSProxyHeader535=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader536=== RUN TestService_AuthMiddleware_MTLSBoundSubjects537=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects538=== RUN TestService_ReadAuthMiddleware539=== PAUSE TestService_ReadAuthMiddleware540=== RUN TestService_AuthMiddleware_OIDC541=== PAUSE TestService_AuthMiddleware_OIDC542=== RUN TestService_RequireScope_OIDC543=== PAUSE TestService_RequireScope_OIDC544=== RUN TestService_ReadScope_PublicByDefault545=== PAUSE TestService_ReadScope_PublicByDefault546=== RUN TestCacheConfigHandler547=== PAUSE TestCacheConfigHandler548=== RUN TestCacheStatsHandler549=== PAUSE TestCacheStatsHandler550=== RUN TestClientCADerivations551=== PAUSE TestClientCADerivations552=== RUN TestClientErrorHandling553=== PAUSE TestClientErrorHandling554=== RUN TestClientIntegration555=== PAUSE TestClientIntegration556=== RUN TestClientMultipleUploads557=== PAUSE TestClientMultipleUploads558=== RUN TestClientWithDependencies559=== PAUSE TestClientWithDependencies560=== RUN TestClientSharedPathCommittedMidPush561=== PAUSE TestClientSharedPathCommittedMidPush562=== RUN TestPinProtectsFromGC563=== PAUSE TestPinProtectsFromGC564=== RUN TestClientPushesUseOnePush565=== PAUSE TestClientPushesUseOnePush566=== RUN TestClientFallsBackToClosures567=== PAUSE TestClientFallsBackToClosures568=== RUN TestDeleteClosuresRacingPins569=== PAUSE TestDeleteClosuresRacingPins570=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock571=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock572=== RUN TestResolveDBConnectionString573=== PAUSE TestResolveDBConnectionString574=== RUN TestConnectWaitsForAPeerMigration575=== PAUSE TestConnectWaitsForAPeerMigration576=== RUN TestLeadElectsOneAndHandsOver577=== PAUSE TestLeadElectsOneAndHandsOver578=== RUN TestLeadIncumbentWinsAfterRestart5792026/11/01 17:55:42 INFO lead: acquired remote=192.0.2.1:12345802026/11/01 17:55:43 INFO lead: released remote=192.0.2.1:12345812026/11/01 17:55:43 INFO lead: acquired remote=192.0.2.1:12345822026/11/01 17:55:44 INFO lead: released remote=192.0.2.1:1234583--- PASS: TestLeadIncumbentWinsAfterRestart (1.98s)584=== RUN TestLeadIncumbentAnnouncesAtOnce585=== PAUSE TestLeadIncumbentAnnouncesAtOnce586=== RUN TestLeadEndsOnShutdown587=== PAUSE TestLeadEndsOnShutdown588=== RUN TestLeadEndsWhenItsConnectionHangs5892026/11/01 17:55:44 INFO lead: acquired remote=192.0.2.1:12345902026-11-01 17:55:45.976 UTC [37071] FATAL: terminating connection due to administrator command5912026/11/01 17:55:46 INFO lead: acquired remote=192.0.2.1:12345922026/11/01 17:55:47 WARN lead: lock connection lost error="timeout: context deadline exceeded"5932026/11/01 17:55:47 INFO lead: released remote=192.0.2.1:12345942026/11/01 17:55:47 INFO lead: released remote=192.0.2.1:1234595--- PASS: TestLeadEndsWhenItsConnectionHangs (2.96s)596=== RUN TestGCAdvisoryLockBlocksConcurrentRun597=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun598=== RUN TestGCBugBareHashReferences599=== PAUSE TestGCBugBareHashReferences600=== RUN TestGCMetrics601=== PAUSE TestGCMetrics602=== RUN TestPushDedupSurvivesConcurrentGC603=== PAUSE TestPushDedupSurvivesConcurrentGC604=== RUN TestDeduplicatedObjectsRecordedAsPending605=== PAUSE TestDeduplicatedObjectsRecordedAsPending606=== RUN TestGCSweepSkipsPendingObjects607=== PAUSE TestGCSweepSkipsPendingObjects608=== RUN TestTombstonedObjectOfferedWithoutWaiting609=== PAUSE TestTombstonedObjectOfferedWithoutWaiting610=== RUN TestGCSweepDeliversEachKeyOnce611=== PAUSE TestGCSweepDeliversEachKeyOnce612=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection613=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection614=== RUN TestForceGCDuringPushOffersSweptObject615=== PAUSE TestForceGCDuringPushOffersSweptObject616=== RUN TestFailedS3DeleteKeepsTombstone617=== PAUSE TestFailedS3DeleteKeepsTombstone618=== RUN TestSweepSkipsRowsLockedByPush619=== PAUSE TestSweepSkipsRowsLockedByPush620=== RUN TestRegisterCompletedObjectNeedsPendingRow621=== PAUSE TestRegisterCompletedObjectNeedsPendingRow622=== RUN TestGetExistingObjectsLocksRows623=== PAUSE TestGetExistingObjectsLocksRows624=== RUN TestSweepRechecksPendingAfterLocking625=== PAUSE TestSweepRechecksPendingAfterLocking626=== RUN TestPushWaitsForSweepHoldingRow627=== PAUSE TestPushWaitsForSweepHoldingRow628=== RUN TestCommitRacingPendingCleanupKeepsObjects629=== PAUSE TestCommitRacingPendingCleanupKeepsObjects630=== RUN TestGCEndsOnShutdown631=== PAUSE TestGCEndsOnShutdown632=== RUN TestGCTaskStore_StartNew633=== PAUSE TestGCTaskStore_StartNew634=== RUN TestGCTaskStore_DeduplicateSameParams635=== PAUSE TestGCTaskStore_DeduplicateSameParams636=== RUN TestGCTaskStore_ConflictDifferentParams637=== PAUSE TestGCTaskStore_ConflictDifferentParams638=== RUN TestGCTaskStore_GetEmpty639=== PAUSE TestGCTaskStore_GetEmpty640=== RUN TestGCTaskStore_GetReturnsLatest641=== PAUSE TestGCTaskStore_GetReturnsLatest642=== RUN TestGCTaskStore_CompletedAllowsNewTask643=== PAUSE TestGCTaskStore_CompletedAllowsNewTask644=== RUN TestGCTaskStore_PhaseUpdates645=== PAUSE TestGCTaskStore_PhaseUpdates646=== RUN TestGCTaskStore_Fail647=== PAUSE TestGCTaskStore_Fail648=== RUN TestGracefulShutdownDrainsInflight649=== PAUSE TestGracefulShutdownDrainsInflight650=== RUN TestService_healthCheckHandler651=== PAUSE TestService_healthCheckHandler652=== RUN TestService_readinessHandler653=== PAUSE TestService_readinessHandler654=== RUN TestGenerateLandingPage655=== PAUSE TestGenerateLandingPage656=== RUN TestCacheConfigHandlerMaxNarSize657=== PAUSE TestCacheConfigHandlerMaxNarSize658=== RUN TestCreatePendingClosureRejectsOversizedNAR659=== PAUSE TestCreatePendingClosureRejectsOversizedNAR660=== RUN TestNARDeduplicationMetadataUploadBug661=== PAUSE TestNARDeduplicationMetadataUploadBug662=== RUN TestMetricsInventory663=== PAUSE TestMetricsInventory664=== RUN TestMetricsCommit665=== PAUSE TestMetricsCommit666=== RUN TestService_NativeMTLS667=== PAUSE TestService_NativeMTLS668=== RUN TestServerTLSConfig669=== PAUSE TestServerTLSConfig670=== RUN TestMultipartCleanup671=== PAUSE TestMultipartCleanup672=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded673=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded674=== RUN TestPendingCleanupUsesOneCutoff675=== PAUSE TestPendingCleanupUsesOneCutoff676=== RUN TestObjectStatsTrigger677=== PAUSE TestObjectStatsTrigger678=== RUN TestObjectStatsUpdatedOncePerCommit679=== PAUSE TestObjectStatsUpdatedOncePerCommit680=== RUN TestOrphanedObjectsGC681=== PAUSE TestOrphanedObjectsGC682=== RUN TestOrphanedObjectsGCStressTest683=== PAUSE TestOrphanedObjectsGCStressTest684=== RUN TestCreatePin_ReservedPins685=== PAUSE TestCreatePin_ReservedPins686=== RUN TestPresentReportsOnlyClosureRoots687=== PAUSE TestPresentReportsOnlyClosureRoots688=== RUN TestPresentRefreshesOnlyStaleClosures689=== PAUSE TestPresentRefreshesOnlyStaleClosures690=== RUN TestPresentNotReportedWhileGCDeletesClosure691=== PAUSE TestPresentNotReportedWhileGCDeletesClosure692=== RUN TestParseSingleRange693=== PAUSE TestParseSingleRange694=== RUN TestProxyHeadersOnlyTrustedOnSocket6952026/11/01 17:55:47 INFO Starting HTTP server address=127.0.0.1:560346962026/11/01 17:55:47 INFO Starting HTTP server address=proxy.sock6972026/11/01 17:55:47 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6982026/11/01 17:55:47 INFO Shutdown signal received, draining in-flight requests timeout=10s699--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)700=== RUN TestIsValidCachePath701=== PAUSE TestIsValidCachePath702=== RUN TestReadProxyNarinfo703=== PAUSE TestReadProxyNarinfo704=== RUN TestReadProxyNarinfoAlreadyDecompressed705=== PAUSE TestReadProxyNarinfoAlreadyDecompressed706=== RUN TestReadProxyContentNegotiation707=== PAUSE TestReadProxyContentNegotiation708=== RUN TestReadProxyNarStreaming709=== PAUSE TestReadProxyNarStreaming710=== RUN TestReadProxy404711=== PAUSE TestReadProxy404712=== RUN TestReadProxyInvalidPath713=== PAUSE TestReadProxyInvalidPath714=== RUN TestReadProxyHead715=== PAUSE TestReadProxyHead716=== RUN TestReadProxyOutlastsServerWriteTimeout717=== PAUSE TestReadProxyOutlastsServerWriteTimeout718=== RUN TestReadProxyConditionalGet719=== PAUSE TestReadProxyConditionalGet720=== RUN TestReadProxyRootRedirectsToIndexHTML721=== PAUSE TestReadProxyRootRedirectsToIndexHTML722=== RUN TestReadProxyDisabled723=== PAUSE TestReadProxyDisabled724=== RUN TestReadRedirectNar725=== PAUSE TestReadRedirectNar726=== RUN TestReadRedirectKeepsNarinfoProxied727=== PAUSE TestReadRedirectKeepsNarinfoProxied728=== RUN TestReadProxyRangeRequest729=== PAUSE TestReadProxyRangeRequest730=== RUN TestReadRedirectUsesPublicS3URL731=== PAUSE TestReadRedirectUsesPublicS3URL732=== RUN TestPush_OverlappingRootsStoreOneRowPerKey733=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey734=== RUN TestPush_CompleteCommitsEveryRoot735=== PAUSE TestPush_CompleteCommitsEveryRoot736=== RUN TestPush_RepeatedRootCommitsOnce737=== PAUSE TestPush_RepeatedRootCommitsOnce738=== RUN TestPush_CompleteWaitsForCleanupOfThePush739=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush740=== RUN TestPush_RootsAreLockedInByteOrder741=== PAUSE TestPush_RootsAreLockedInByteOrder742=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit743=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit744=== RUN TestPush_RejectsBadRequests745=== PAUSE TestPush_RejectsBadRequests746=== RUN TestPush_SignsNarinfosOfItsPendingObjects747=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects748=== RUN TestRedundantMultipartUpload749=== PAUSE TestRedundantMultipartUpload750=== RUN TestCompleteMultipartUpload_ErrorButObjectExists751=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists752=== RUN TestCompletedNarNotReofferedAcrossClosures753=== PAUSE TestCompletedNarNotReofferedAcrossClosures754=== RUN TestPresignedUploadRegisteredBeforeCommit755=== PAUSE TestPresignedUploadRegisteredBeforeCommit756=== RUN TestService_Rustfstest757=== PAUSE TestService_Rustfstest758=== RUN TestParseSize759=== PAUSE TestParseSize760=== RUN TestSkippedUploadsHandler761=== PAUSE TestSkippedUploadsHandler762=== RUN TestSystemdListenerNotActivated763--- PASS: TestSystemdListenerNotActivated (0.00s)764=== RUN TestWatchdogBeatsWhenHealthy765--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)766=== RUN TestWatchdogSkipsWhenUnhealthy7672026/11/01 17:55:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/11/01 17:55:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/11/01 17:55:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/01 17:55:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/01 17:55:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/01 17:55:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/01 17:55:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/01 17:55:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/01 17:55:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/11/01 17:55:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"777--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)778=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle779=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle780=== RUN TestProxyWriteTimeout781=== PAUSE TestProxyWriteTimeout782=== RUN TestPendingClosureWriteTimeout783=== PAUSE TestPendingClosureWriteTimeout784=== RUN TestIsValidUploadKey785=== PAUSE TestIsValidUploadKey786=== RUN TestUploadHandlersRejectInvalidKeys787=== PAUSE TestUploadHandlersRejectInvalidKeys788=== RUN TestUploadHandlersRejectOversizedBody789=== PAUSE TestUploadHandlersRejectOversizedBody790=== RUN TestService_cleanupPendingClosuresHandler791=== PAUSE TestService_cleanupPendingClosuresHandler792=== RUN TestService_createPendingClosureHandler793=== PAUSE TestService_createPendingClosureHandler794=== RUN TestService_verifyS3Integrity795=== PAUSE TestService_verifyS3Integrity796=== RUN TestService_verifyS3ReuploadsStaleNarinfo797=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo798=== RUN TestCompleteMultipartUnregistered799=== PAUSE TestCompleteMultipartUnregistered800=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT801=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT802=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle803=== CONT TestService_AuthMiddleware804=== CONT TestCreatePin_ReservedPins805=== CONT TestOrphanedObjectsGCStressTest806=== CONT TestPresentReportsOnlyClosureRoots807=== CONT TestSkippedUploadsHandler808=== CONT TestOrphanedObjectsGC809=== CONT TestService_cleanupPendingClosuresHandler810=== CONT TestParseSize811--- PASS: TestParseSize (0.00s)812=== CONT TestPush_RejectsBadRequests813=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT814=== CONT TestObjectStatsUpdatedOncePerCommit815=== CONT TestService_Rustfstest816=== CONT TestCompleteMultipartUnregistered8172026/11/01 17:55:47 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000818=== CONT TestService_verifyS3ReuploadsStaleNarinfo819=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed820=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed821=== CONT TestPresignedUploadRegisteredBeforeCommit822=== CONT TestObjectStatsTrigger823=== CONT TestService_verifyS3Integrity824=== CONT TestService_createPendingClosureHandler825=== CONT TestCompletedNarNotReofferedAcrossClosures826=== CONT TestPendingCleanupUsesOneCutoff827=== CONT TestCompleteMultipartUpload_ErrorButObjectExists828=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded829=== CONT TestRedundantMultipartUpload830=== CONT TestPush_SignsNarinfosOfItsPendingObjects831=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed832=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed833=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost834=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost835=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed836=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed837=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed838=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed839=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit840--- PASS: TestSkippedUploadsHandler (0.04s)841=== CONT TestPush_RootsAreLockedInByteOrder8422026/11/01 17:55:48 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56037/oidc843--- PASS: TestService_Rustfstest (0.88s)844=== CONT TestPush_CompleteWaitsForCleanupOfThePush8452026/11/01 17:55:49 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"846--- PASS: TestService_AuthMiddleware (1.40s)847=== CONT TestTombstonedObjectOfferedWithoutWaiting8482026/11/01 17:55:49 INFO Received uploads request method=POST path=/api/pending_closures8492026/11/01 17:55:49 INFO Received uploads request method=POST path=/api/pending_closures8502026/11/01 17:55:49 INFO Received uploads request method=POST path=/api/pending_closures851--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.12s)852=== CONT TestPush_RepeatedRootCommitsOnce8532026/11/01 17:55:50 INFO Received uploads request method=POST path=/api/pending_closures8542026/11/01 17:55:50 INFO Received uploads request method=POST path=/api/pending_closures8552026/11/01 17:55:50 INFO Received cleanup request method=DELETE path=/api/pending_closures856=== NAME TestOrphanedObjectsGC857 orphaned_objects_gc_test.go:287: GC Test Summary:858 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A859 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B860 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)861 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)862 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects863--- PASS: TestOrphanedObjectsGC (3.00s)864=== CONT TestPush_CompleteCommitsEveryRoot8652026/11/01 17:55:50 INFO Received uploads request method=POST path=/api/pending_closures8662026/11/01 17:55:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8672026/11/01 17:55:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete868--- PASS: TestObjectStatsUpdatedOncePerCommit (3.59s)8692026/11/01 17:55:51 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst870=== CONT TestGCSweepDeliversEachKeyOnce871--- PASS: TestCompleteMultipartUnregistered (3.60s)872=== CONT TestPush_OverlappingRootsStoreOneRowPerKey8732026/11/01 17:55:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8742026/11/01 17:55:51 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLjNkYjMzOWVkLWQwYzEtNGVlOC1hZWJjLTU5YzIyMWE4MjhlN3gxNzkzNTU1NzQ5NTY2MzE3MDAw parts=128752026/11/01 17:55:51 INFO Received uploads request method=POST path=/api/pending_closures8762026/11/01 17:55:51 INFO Received uploads request method=POST path=/api/pending_closures877--- PASS: TestPresentReportsOnlyClosureRoots (3.94s)878=== CONT TestReadRedirectUsesPublicS3URL879--- PASS: TestObjectStatsTrigger (4.24s)880=== CONT TestReadProxyRangeRequest8812026/11/01 17:55:52 INFO Received uploads request method=POST path=/api/pending_closures882--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (4.56s)883=== CONT TestReadRedirectKeepsNarinfoProxied8842026/11/01 17:55:52 INFO Received push request method=POST path=/api/pushes8852026/11/01 17:55:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8862026/11/01 17:55:52 INFO Signed narinfos id=1 count=18872026/11/01 17:55:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8882026/11/01 17:55:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8892026/11/01 17:55:52 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"8902026/11/01 17:55:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8912026/11/01 17:55:52 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"8922026/11/01 17:55:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8932026/11/01 17:55:52 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=18942026/11/01 17:55:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8952026/11/01 17:55:52 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo896--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (4.92s)897=== CONT TestReadRedirectNar8982026/11/01 17:55:52 INFO Received uploads request method=POST path=/api/pending_closures8992026/11/01 17:55:52 INFO Received uploads request method=POST path=/api/pending_closures9002026/11/01 17:55:52 INFO Received uploads request method=POST path=/api/pending_closures9012026/11/01 17:55:53 INFO Received uploads request method=POST path=/api/pending_closures9022026/11/01 17:55:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9032026/11/01 17:55:53 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLjZiZWFmMDdmLWE3OTctNDc2Zi1iMmY3LTc5ZjczYzYyZDBmNngxNzkzNTU1NzUxNTg2MjY5MDAw error="Get \"http://127.0.0.1:1/bucket7/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"9042026/11/01 17:55:53 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLjkyN2YyYWY3LTdhNzctNGI3YS1hNmQ1LThmYmUxNDBjMmZlM3gxNzkzNTU1NzUxNTQ2Nzc3MDAw parts=129052026/11/01 17:55:53 INFO Received cleanup request method=DELETE path=/api/pending_closures9062026/11/01 17:55:53 INFO Aborted multipart uploads count=1 kept=0907--- PASS: TestRedundantMultipartUpload (5.71s)908=== CONT TestGCSweepSkipsPendingObjects9092026/11/01 17:55:53 INFO Received cleanup request method=DELETE path=/api/pending_closures9102026/11/01 17:55:53 INFO Aborted multipart uploads count=0 kept=09112026/11/01 17:55:53 INFO Received uploads request method=POST path=/api/pending_closures9122026/11/01 17:55:53 INFO Received cleanup request method=DELETE path=/api/pending_closures9132026/11/01 17:55:53 INFO Aborted multipart uploads count=1 kept=09142026/11/01 17:55:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9152026-11-01 17:55:53.778 UTC [37139] ERROR: Closure does not exist: id=19162026-11-01 17:55:53.778 UTC [37139] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9172026-11-01 17:55:53.778 UTC [37139] STATEMENT: -- name: CommitPendingClosure :one918 SELECT commit_pending_closure($1::bigint)::bigint919 920--- PASS: TestService_cleanupPendingClosuresHandler (6.00s)921=== CONT TestReadProxyDisabled9222026/11/01 17:55:53 INFO Received uploads request method=POST path=/api/pending_closures9232026/11/01 17:55:54 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9242026/11/01 17:55:54 INFO Received uploads request method=POST path=/api/pending_closures925--- PASS: TestPresignedUploadRegisteredBeforeCommit (6.39s)926=== CONT TestReadProxyRootRedirectsToIndexHTML9272026/11/01 17:55:54 INFO Received push request method=POST path=/api/pushes9282026-11-01 17:55:54.555 UTC [37184] ERROR: could not obtain lock on row in relation "closures"9292026-11-01 17:55:54.555 UTC [37184] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9302026-11-01 17:55:54.557 UTC [37184] ERROR: could not obtain lock on row in relation "closures"9312026-11-01 17:55:54.557 UTC [37184] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9322026-11-01 17:55:54.563 UTC [37184] ERROR: could not obtain lock on row in relation "closures"9332026-11-01 17:55:54.563 UTC [37184] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9342026-11-01 17:55:54.570 UTC [37184] ERROR: could not obtain lock on row in relation "closures"9352026-11-01 17:55:54.570 UTC [37184] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9362026-11-01 17:55:54.575 UTC [37184] ERROR: could not obtain lock on row in relation "closures"9372026-11-01 17:55:54.575 UTC [37184] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT938--- PASS: TestPush_RootsAreLockedInByteOrder (6.78s)939=== CONT TestDeduplicatedObjectsRecordedAsPending9402026/11/01 17:55:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9412026/11/01 17:55:54 INFO Received uploads request method=POST path=/api/pending_closures9422026/11/01 17:55:54 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLmY4NDU4Yjg3LTZkZDEtNDMzYy04OTQ4LWQ3ZjE1YmFlN2JjMHgxNzkzNTU1NzUyODQ2NjU2MDAw parts=109432026/11/01 17:55:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9442026/11/01 17:55:54 INFO Completed upload id=1 objects=2 duration=34.953916ms9452026/11/01 17:55:54 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009462026/11/01 17:55:54 INFO Received uploads request method=POST path=/api/pending_closures9472026/11/01 17:55:54 INFO Starting cleanup of old closures method=DELETE path=/api/closures9482026/11/01 17:55:54 INFO Aborted multipart uploads count=0 kept=09492026/11/01 17:55:54 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=09502026/11/01 17:55:55 INFO Vacuumed table table=pending_closures9512026/11/01 17:55:55 INFO Vacuumed table table=pending_objects9522026/11/01 17:55:55 INFO Vacuumed table table=multipart_uploads9532026/11/01 17:55:55 INFO Vacuumed table table=closures9542026/11/01 17:55:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9552026/11/01 17:55:55 INFO Received push request method=POST path=/api/pushes9562026/11/01 17:55:55 INFO Vacuumed table table=objects9572026/11/01 17:55:55 INFO Received get closure request method=GET path=/api/closures/00000000000000000000000000000000958--- PASS: TestService_createPendingClosureHandler (7.44s)959=== CONT TestReadProxyConditionalGet9602026/11/01 17:55:55 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLmRhYjJjMjJhLWI1NDItNDI3Ni1iNWFhLTM5MTcxMjljOGEyOHgxNzkzNTU1NzUzMjQ5MTAyMDAw parts=109612026/11/01 17:55:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9622026/11/01 17:55:55 INFO Received complete push request method=POST path=/api/pushes/1/complete9632026/11/01 17:55:55 INFO Completed upload id=1 objects=2 duration=32.697917ms9642026/11/01 17:55:55 WARN Rate limiter enabled after throttle name=s3-test rate=59652026/11/01 17:55:55 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."9662026/11/01 17:55:55 INFO Received uploads request method=POST path=/api/pending_closures967=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle968 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=10969 throttle_test.go:215: Rate limiter: enabled=true, rate=5.00970--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (7.59s)971=== CONT TestPushDedupSurvivesConcurrentGC9722026/11/01 17:55:55 INFO Received uploads request method=POST path=/api/pending_closures9732026/11/01 17:55:55 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9742026/11/01 17:55:55 WARN Found objects in DB but missing from S3, will re-upload count=1975--- PASS: TestService_verifyS3Integrity (7.61s)976=== CONT TestMultipartCleanup9772026/11/01 17:55:55 INFO Completed push id=1 objects=4 duration=42.820625ms9782026/11/01 17:55:55 INFO Received push request method=POST path=/api/pushes9792026/11/01 17:55:55 INFO Aborted multipart uploads count=0 kept=09802026/11/01 17:55:55 WARN Force mode enabled - objects will be deleted immediately without grace period9812026/11/01 17:55:55 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=0982=== RUN TestPush_RejectsBadRequests/no_roots983=== PAUSE TestPush_RejectsBadRequests/no_roots9842026/11/01 17:55:55 INFO Vacuumed table table=pending_closures985=== RUN TestPush_RejectsBadRequests/no_objects986=== PAUSE TestPush_RejectsBadRequests/no_objects987=== RUN TestPush_RejectsBadRequests/bad_root988=== PAUSE TestPush_RejectsBadRequests/bad_root989=== RUN TestPush_RejectsBadRequests/root_not_in_objects990=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects991=== CONT TestGCMetrics9922026/11/01 17:55:55 INFO Vacuumed table table=pending_objects9932026/11/01 17:55:55 INFO Vacuumed table table=multipart_uploads9942026/11/01 17:55:55 INFO Vacuumed table table=closures9952026/11/01 17:55:55 INFO Vacuumed table table=objects9962026/11/01 17:55:55 INFO Received complete push request method=POST path=/api/pushes/2/complete9972026/11/01 17:55:55 INFO Completed push id=2 objects=4 duration=13.04225ms998--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (8.01s)999=== CONT TestReadProxyOutlastsServerWriteTimeout10002026/11/01 17:55:55 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10012026/11/01 17:55:55 WARN Refused reserved pin name=worker-x86_64-linux10022026/11/01 17:55:55 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10032026/11/01 17:55:55 INFO Received create pin request method=POST path=/api/pins/my-app10042026/11/01 17:55:55 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1005--- PASS: TestCreatePin_ReservedPins (8.13s)1006=== CONT TestServerTLSConfig1007=== RUN TestServerTLSConfig/no_client_CA1008=== PAUSE TestServerTLSConfig/no_client_CA1009=== RUN TestServerTLSConfig/missing_CA_file1010=== PAUSE TestServerTLSConfig/missing_CA_file1011=== RUN TestServerTLSConfig/not_a_PEM_file1012=== PAUSE TestServerTLSConfig/not_a_PEM_file1013=== CONT TestGCBugBareHashReferences10142026/11/01 17:55:56 INFO Aborted multipart uploads count=1 kept=010152026/11/01 17:55:56 INFO Received cleanup request method=DELETE path=/api/pending_closures10162026/11/01 17:55:56 INFO Aborted multipart uploads count=1 kept=01017--- PASS: TestPendingCleanupUsesOneCutoff (8.51s)1018=== CONT TestReadProxyHead10192026/11/01 17:55:56 INFO Received uploads request method=POST path=/api/pending_closures10202026/11/01 17:55:56 INFO Received push request method=POST path=/api/pushes10212026/11/01 17:55:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10222026/11/01 17:55:56 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLjQxNjZjMzczLTEzN2MtNGFmNi1iZWU3LTllNmJmOTFmNTRiMHgxNzkzNTU1NzU2NDQzNzA4MDAw10232026/11/01 17:55:56 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLjQxNjZjMzczLTEzN2MtNGFmNi1iZWU3LTllNmJmOTFmNTRiMHgxNzkzNTU1NzU2NDQzNzA4MDAw parts=11024--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (9.12s)1025=== CONT TestGCAdvisoryLockBlocksConcurrentRun10262026/11/01 17:55:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10272026/11/01 17:55:57 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLjlkYjBlMzlkLTExNzQtNGNiMi1hNGQyLTdkM2Y2MDE5N2E4OHgxNzkzNTU1NzU0ODMzMzQyMDAw parts=1210282026/11/01 17:55:57 INFO Received uploads request method=POST path=/api/pending_closures10292026/11/01 17:55:57 INFO Received uploads request method=POST path=/api/pending_closures1030--- PASS: TestCompletedNarNotReofferedAcrossClosures (9.41s)1031=== CONT TestReadProxyInvalidPath10322026-11-01 17:55:57.227 UTC [37209] ERROR: Push does not exist: id=110332026-11-01 17:55:57.227 UTC [37209] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE10342026-11-01 17:55:57.227 UTC [37209] STATEMENT: SELECT commit_push($1)1035--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (8.58s)1036=== CONT TestLeadEndsOnShutdown1037--- PASS: TestTombstonedObjectOfferedWithoutWaiting (8.07s)1038=== CONT TestReadProxy40410392026/11/01 17:55:57 INFO Received push request method=POST path=/api/pushes10402026/11/01 17:55:57 INFO Received complete push request method=POST path=/api/pushes/1/complete10412026/11/01 17:55:57 INFO Completed push id=1 objects=4 duration=67.127083ms1042--- PASS: TestPush_RepeatedRootCommitsOnce (7.85s)1043=== CONT TestLeadIncumbentAnnouncesAtOnce10442026/11/01 17:55:57 INFO Received push request method=POST path=/api/pushes10452026/11/01 17:55:58 INFO Received complete push request method=POST path=/api/pushes/1/complete10462026/11/01 17:55:58 INFO Completed push id=1 objects=6 duration=56.64775ms1047--- PASS: TestPush_CompleteCommitsEveryRoot (7.42s)1048=== CONT TestLeadElectsOneAndHandsOver10492026/11/01 17:55:58 INFO Aborted multipart uploads count=0 kept=010502026/11/01 17:55:58 WARN Force mode enabled - objects will be deleted immediately without grace period10512026/11/01 17:55:58 INFO Received push request method=POST path=/api/pushes1052--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (7.52s)1053=== CONT TestReadProxyNarStreaming10542026/11/01 17:55:59 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=010552026/11/01 17:55:59 INFO Vacuumed table table=pending_closures10562026/11/01 17:55:59 INFO Vacuumed table table=pending_objects1057--- PASS: TestReadRedirectUsesPublicS3URL (7.55s)1058=== CONT TestService_NativeMTLS10592026/11/01 17:55:59 INFO Vacuumed table table=multipart_uploads10602026/11/01 17:55:59 INFO Vacuumed table table=closures10612026/11/01 17:55:59 INFO Vacuumed table table=objects1062--- PASS: TestGCSweepDeliversEachKeyOnce (7.93s)1063=== CONT TestReadProxyContentNegotiation1064--- PASS: TestReadProxyRangeRequest (7.57s)1065=== CONT TestMetricsCommit1066--- PASS: TestReadRedirectKeepsNarinfoProxied (7.51s)1067=== CONT TestReadProxyNarinfoAlreadyDecompressed1068--- PASS: TestReadRedirectNar (7.44s)1069=== CONT TestMetricsInventory10702026/11/01 17:56:00 INFO Received uploads request method=POST path=/api/pending_closures10712026/11/01 17:56:00 INFO Aborted multipart uploads count=0 kept=010722026/11/01 17:56:00 WARN Force mode enabled - objects will be deleted immediately without grace period10732026/11/01 17:56:00 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010742026/11/01 17:56:00 INFO Vacuumed table table=pending_closures10752026/11/01 17:56:00 INFO Vacuumed table table=pending_objects10762026/11/01 17:56:00 INFO Vacuumed table table=multipart_uploads10772026/11/01 17:56:00 INFO Vacuumed table table=closures10782026/11/01 17:56:00 INFO Vacuumed table table=objects1079--- PASS: TestGCSweepSkipsPendingObjects (7.21s)1080=== CONT TestNARDeduplicationMetadataUploadBug1081--- PASS: TestReadProxyDisabled (6.93s)1082=== CONT TestReadProxyNarinfo1083--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.86s)1084=== CONT TestCreatePendingClosureRejectsOversizedNAR10852026/11/01 17:56:01 INFO Received uploads request method=POST path=/api/pending_closures1086--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1087=== CONT TestIsValidCachePath1088=== RUN TestIsValidCachePath/narinfo1089=== PAUSE TestIsValidCachePath/narinfo1090=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1091=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1092=== RUN TestIsValidCachePath/nar_zst1093=== PAUSE TestIsValidCachePath/nar_zst1094=== RUN TestIsValidCachePath/nar_xz1095=== PAUSE TestIsValidCachePath/nar_xz1096=== RUN TestIsValidCachePath/nar_bz21097=== PAUSE TestIsValidCachePath/nar_bz21098=== RUN TestIsValidCachePath/nar_uncompressed1099=== PAUSE TestIsValidCachePath/nar_uncompressed1100=== RUN TestIsValidCachePath/ls1101=== PAUSE TestIsValidCachePath/ls1102=== RUN TestIsValidCachePath/log1103=== PAUSE TestIsValidCachePath/log1104=== RUN TestIsValidCachePath/realisation1105=== PAUSE TestIsValidCachePath/realisation1106=== RUN TestIsValidCachePath/nix-cache-info1107=== PAUSE TestIsValidCachePath/nix-cache-info1108=== RUN TestIsValidCachePath/index.html1109=== PAUSE TestIsValidCachePath/index.html1110=== RUN TestIsValidCachePath/traversal_parent1111=== PAUSE TestIsValidCachePath/traversal_parent1112=== RUN TestIsValidCachePath/traversal_in_middle1113=== PAUSE TestIsValidCachePath/traversal_in_middle1114=== RUN TestIsValidCachePath/invalid_char_e1115=== PAUSE TestIsValidCachePath/invalid_char_e1116=== RUN TestIsValidCachePath/invalid_char_u1117=== PAUSE TestIsValidCachePath/invalid_char_u1118=== RUN TestIsValidCachePath/random_path1119=== PAUSE TestIsValidCachePath/random_path1120=== RUN TestIsValidCachePath/empty1121=== PAUSE TestIsValidCachePath/empty1122=== RUN TestIsValidCachePath/leading_slash1123=== PAUSE TestIsValidCachePath/leading_slash1124=== RUN TestIsValidCachePath/wrong_extension1125=== PAUSE TestIsValidCachePath/wrong_extension1126=== RUN TestIsValidCachePath/short_hash1127=== PAUSE TestIsValidCachePath/short_hash1128=== CONT TestConnectWaitsForAPeerMigration11292026/11/01 17:56:01 INFO Received uploads request method=POST path=/api/pending_closures1130--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.76s)1131=== CONT TestCacheConfigHandlerMaxNarSize1132--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1133=== CONT TestParseSingleRange1134=== RUN TestParseSingleRange/none1135=== PAUSE TestParseSingleRange/none1136=== RUN TestParseSingleRange/unknown_unit1137=== PAUSE TestParseSingleRange/unknown_unit1138=== RUN TestParseSingleRange/multi-range_ignored1139=== PAUSE TestParseSingleRange/multi-range_ignored1140=== RUN TestParseSingleRange/malformed_no_dash1141=== PAUSE TestParseSingleRange/malformed_no_dash1142=== RUN TestParseSingleRange/malformed_both_empty1143=== PAUSE TestParseSingleRange/malformed_both_empty1144=== RUN TestParseSingleRange/malformed_end_before_start1145=== PAUSE TestParseSingleRange/malformed_end_before_start1146=== RUN TestParseSingleRange/closed1147=== PAUSE TestParseSingleRange/closed1148=== RUN TestParseSingleRange/open-ended1149=== PAUSE TestParseSingleRange/open-ended1150=== RUN TestParseSingleRange/end_clamped_to_size1151=== PAUSE TestParseSingleRange/end_clamped_to_size1152=== RUN TestParseSingleRange/suffix1153=== PAUSE TestParseSingleRange/suffix1154=== RUN TestParseSingleRange/suffix_exceeds_size1155=== PAUSE TestParseSingleRange/suffix_exceeds_size1156=== RUN TestParseSingleRange/single_byte1157=== PAUSE TestParseSingleRange/single_byte1158=== RUN TestParseSingleRange/start_past_EOF1159=== PAUSE TestParseSingleRange/start_past_EOF1160=== RUN TestParseSingleRange/start_far_past_EOF1161=== PAUSE TestParseSingleRange/start_far_past_EOF1162=== CONT TestResolveDBConnectionString1163=== RUN TestResolveDBConnectionString/flag_wins1164=== PAUSE TestResolveDBConnectionString/flag_wins1165=== RUN TestResolveDBConnectionString/file_when_flag_empty1166=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1167=== RUN TestResolveDBConnectionString/missing_file_is_an_error1168=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1169=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1170=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1171=== RUN TestResolveDBConnectionString/nothing_configured1172=== PAUSE TestResolveDBConnectionString/nothing_configured1173=== CONT TestPresentNotReportedWhileGCDeletesClosure1174=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1175=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1176=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1177=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1178=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock11792026/11/01 17:56:01 INFO Received uploads request method=POST path=/api/pending_closures11802026/11/01 17:56:01 INFO Received cleanup request method=DELETE path=/api/pending_closures11812026/11/01 17:56:01 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket42/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""11822026/11/01 17:56:01 INFO Aborted multipart uploads count=0 kept=111832026/11/01 17:56:01 INFO Received cleanup request method=DELETE path=/api/pending_closures11842026/11/01 17:56:01 INFO Aborted multipart uploads count=1 kept=01185--- PASS: TestMultipartCleanup (6.48s)1186=== CONT TestDeleteClosuresRacingPins11872026/11/01 17:56:02 INFO Received uploads request method=POST path=/api/pending_closures11882026/11/01 17:56:02 INFO Aborted multipart uploads count=0 kept=01189--- PASS: TestReadProxyConditionalGet (7.00s)1190=== CONT TestPresentRefreshesOnlyStaleClosures11912026/11/01 17:56:02 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=011922026/11/01 17:56:02 INFO Vacuumed table table=pending_closures11932026/11/01 17:56:02 INFO Vacuumed table table=pending_objects11942026/11/01 17:56:02 INFO Vacuumed table table=multipart_uploads11952026/11/01 17:56:02 INFO Vacuumed table table=closures11962026/11/01 17:56:02 INFO Vacuumed table table=objects11972026/11/01 17:56:02 INFO Aborted multipart uploads count=0 kept=011982026/11/01 17:56:02 WARN Force mode enabled - objects will be deleted immediately without grace period11992026/11/01 17:56:02 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012002026/11/01 17:56:02 INFO Vacuumed table table=pending_closures12012026/11/01 17:56:02 INFO Vacuumed table table=pending_objects12022026/11/01 17:56:02 INFO Vacuumed table table=multipart_uploads12032026/11/01 17:56:02 INFO Vacuumed table table=closures12042026/11/01 17:56:02 INFO Vacuumed table table=objects1205--- PASS: TestPushDedupSurvivesConcurrentGC (7.06s)1206=== CONT TestIsValidUploadKey1207=== RUN TestIsValidUploadKey/narinfo1208=== PAUSE TestIsValidUploadKey/narinfo1209=== RUN TestIsValidUploadKey/nar_zst1210=== PAUSE TestIsValidUploadKey/nar_zst1211=== RUN TestIsValidUploadKey/nar_xz1212=== PAUSE TestIsValidUploadKey/nar_xz1213=== RUN TestIsValidUploadKey/nar_plain1214=== PAUSE TestIsValidUploadKey/nar_plain1215=== RUN TestIsValidUploadKey/listing1216=== PAUSE TestIsValidUploadKey/listing1217=== RUN TestIsValidUploadKey/build_log1218=== PAUSE TestIsValidUploadKey/build_log1219=== RUN TestIsValidUploadKey/build_log_home-manager_file1220=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1221=== RUN TestIsValidUploadKey/build_log_plus_in_name1222=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1223=== RUN TestIsValidUploadKey/build_log_question_mark1224=== PAUSE TestIsValidUploadKey/build_log_question_mark1225=== RUN TestIsValidUploadKey/build_log_equals1226=== PAUSE TestIsValidUploadKey/build_log_equals1227=== RUN TestIsValidUploadKey/realisation1228=== PAUSE TestIsValidUploadKey/realisation1229=== RUN TestIsValidUploadKey/realisation_plus_in_output1230=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1231=== RUN TestIsValidUploadKey/nix-cache-info1232=== PAUSE TestIsValidUploadKey/nix-cache-info1233=== RUN TestIsValidUploadKey/index.html1234=== PAUSE TestIsValidUploadKey/index.html1235=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1236=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1237=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1238=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1239=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1240=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1241=== RUN TestIsValidUploadKey/traversal1242=== PAUSE TestIsValidUploadKey/traversal1243=== RUN TestIsValidUploadKey/traversal_nar1244=== PAUSE TestIsValidUploadKey/traversal_nar1245=== RUN TestIsValidUploadKey/absolute1246=== PAUSE TestIsValidUploadKey/absolute1247=== RUN TestIsValidUploadKey/empty_key1248=== PAUSE TestIsValidUploadKey/empty_key1249=== RUN TestIsValidUploadKey/unknown_type1250=== PAUSE TestIsValidUploadKey/unknown_type1251=== CONT TestUploadHandlersRejectOversizedBody12522026/11/01 17:56:02 INFO Aborted multipart uploads count=0 kept=012532026/11/01 17:56:02 WARN Force mode enabled - objects will be deleted immediately without grace period12542026/11/01 17:56:02 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012552026/11/01 17:56:02 INFO Vacuumed table table=pending_closures12562026/11/01 17:56:02 INFO Vacuumed table table=pending_objects1257=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1258=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1259=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1260=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1261=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1262=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1263=== CONT TestUploadHandlersRejectInvalidKeys1264=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1265=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1266=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1267=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1268=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1269=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1270=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1271=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1272=== CONT TestGenerateLandingPage12732026/11/01 17:56:02 INFO Vacuumed table table=multipart_uploads12742026/11/01 17:56:02 INFO Vacuumed table table=closures1275--- PASS: TestGenerateLandingPage (0.00s)1276=== CONT TestService_readinessHandler12772026/11/01 17:56:02 INFO Vacuumed table table=objects1278--- PASS: TestGCMetrics (7.04s)1279=== CONT TestClientFallsBackToClosures1280=== NAME TestOrphanedObjectsGCStressTest1281 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1282 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1283--- PASS: TestGCBugBareHashReferences (7.38s)1284=== CONT TestCacheStatsHandler1285--- PASS: TestReadProxyHead (7.00s)1286=== CONT TestCacheConfigHandler1287=== RUN TestCacheConfigHandler/full_config,_no_issuer1288=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1289=== RUN TestCacheConfigHandler/no_cache_url_configured1290=== PAUSE TestCacheConfigHandler/no_cache_url_configured1291=== RUN TestCacheConfigHandler/no_signing_keys1292=== PAUSE TestCacheConfigHandler/no_signing_keys1293=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1294=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1295=== CONT TestService_healthCheckHandler12962026/11/01 17:56:03 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld8 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1297--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (6.64s)1298=== CONT TestGracefulShutdownDrainsInflight12992026/11/01 17:56:03 INFO Starting HTTP server address=127.0.0.1:5619713002026/11/01 17:56:03 INFO Shutdown signal received, draining in-flight requests timeout=10s1301--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1302=== CONT TestGCTaskStore_Fail1303--- PASS: TestGCTaskStore_Fail (0.00s)1304=== CONT TestClientCADerivations13052026/11/01 17:56:03 INFO lead: acquired remote=192.0.2.1:12341306--- PASS: TestReadProxyInvalidPath (6.93s)1307=== CONT TestClientPushesUseOnePush13082026/11/01 17:56:04 INFO lead: acquired remote=192.0.2.1:123413092026/11/01 17:56:04 INFO lead: released remote=192.0.2.1:12341310--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.98s)1311=== CONT TestGCTaskStore_PhaseUpdates1312--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1313=== CONT TestGCTaskStore_CompletedAllowsNewTask1314--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1315=== CONT TestPinProtectsFromGC13162026/11/01 17:56:04 INFO lead: released remote=192.0.2.1:12341317--- PASS: TestLeadEndsOnShutdown (7.68s)1318=== CONT TestClientSharedPathCommittedMidPush1319--- PASS: TestReadProxy404 (7.74s)1320=== CONT TestGCTaskStore_GetReturnsLatest1321--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1322=== CONT TestService_ReadScope_PublicByDefault13232026/11/01 17:56:05 INFO lead: acquired remote=192.0.2.1:12341324--- PASS: TestReadProxyNarStreaming (6.52s)1325=== CONT TestClientWithDependencies13262026/11/01 17:56:05 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13272026/11/01 17:56:05 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1328--- PASS: TestService_NativeMTLS (6.41s)1329=== CONT TestService_RequireScope_OIDC13302026/11/01 17:56:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56221/oidc1331--- PASS: TestReadProxyContentNegotiation (6.87s)1332=== CONT TestClientMultipleUploads13332026/11/01 17:56:06 INFO lead: released remote=192.0.2.1:123413342026/11/01 17:56:06 INFO Received push request method=POST path=/api/pushes13352026/11/01 17:56:06 INFO lead: acquired remote=192.0.2.1:123413362026/11/01 17:56:06 INFO Received complete push request method=POST path=/api/pushes/1/complete13372026/11/01 17:56:06 INFO Completed push id=1 objects=4 duration=39.193708ms13382026/11/01 17:56:06 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13392026/11/01 17:56:06 INFO Completed upload id=2 objects=2 duration=4.528833ms1340--- PASS: TestMetricsCommit (6.95s)1341=== CONT TestGCTaskStore_GetEmpty1342--- PASS: TestGCTaskStore_GetEmpty (0.00s)1343=== CONT TestGCTaskStore_ConflictDifferentParams1344--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1345=== CONT TestGCTaskStore_DeduplicateSameParams1346--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1347=== CONT TestClientIntegration1348--- PASS: TestReadProxyNarinfoAlreadyDecompressed (6.85s)1349=== CONT TestGCTaskStore_StartNew1350--- PASS: TestGCTaskStore_StartNew (0.00s)1351=== CONT TestClientErrorHandling1352=== RUN TestClientErrorHandling/InvalidStorePath1353=== PAUSE TestClientErrorHandling/InvalidStorePath1354=== RUN TestClientErrorHandling/InvalidAuthToken1355=== PAUSE TestClientErrorHandling/InvalidAuthToken1356=== RUN TestClientErrorHandling/ServerNotAvailable1357=== PAUSE TestClientErrorHandling/ServerNotAvailable1358=== CONT TestPendingClosureWriteTimeout1359=== RUN TestPendingClosureWriteTimeout/empty1360=== PAUSE TestPendingClosureWriteTimeout/empty1361=== RUN TestPendingClosureWriteTimeout/400_objects1362=== PAUSE TestPendingClosureWriteTimeout/400_objects1363=== RUN TestPendingClosureWriteTimeout/670k_objects1364=== PAUSE TestPendingClosureWriteTimeout/670k_objects1365=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1366=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1367=== CONT TestService_AuthMiddleware_OIDC13682026/11/01 17:56:06 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56236/oidc1369--- PASS: TestMetricsInventory (6.88s)1370=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1371--- PASS: TestReadProxyOutlastsServerWriteTimeout (11.24s)1372=== CONT TestService_AuthMiddleware_MTLSProxyHeader13732026/11/01 17:56:07 INFO lead: released remote=192.0.2.1:12341374--- PASS: TestLeadElectsOneAndHandsOver (9.17s)1375=== CONT TestService_ReadAuthMiddleware13762026/11/01 17:56:07 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1377--- PASS: TestReadProxyNarinfo (7.09s)1378=== CONT TestProxyWriteTimeout1379=== RUN TestProxyWriteTimeout/narinfo1380=== PAUSE TestProxyWriteTimeout/narinfo1381=== RUN TestProxyWriteTimeout/1_GiB_nar1382=== PAUSE TestProxyWriteTimeout/1_GiB_nar1383=== RUN TestProxyWriteTimeout/10_GiB_nar1384=== PAUSE TestProxyWriteTimeout/10_GiB_nar1385=== RUN TestProxyWriteTimeout/unknown_size1386=== PAUSE TestProxyWriteTimeout/unknown_size1387=== CONT TestRegisterCompletedObjectNeedsPendingRow1388=== NAME TestNARDeduplicationMetadataUploadBug1389 metadata_upload_test.go:48: First store path: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestNARDeduplicationMetadataUploadBug3372347373/001/store/hc0rps3qq7rmink5rzbl9v303gdbxmfc-file1.txt13902026/11/01 17:56:08 INFO Received push request method=POST path=/api/pushes13912026/11/01 17:56:08 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13922026/11/01 17:56:08 INFO Uploading hc0rps3qq7rmink5rzbl9v303gdbxmfc-file1.txt (160B)1393--- PASS: TestConnectWaitsForAPeerMigration (7.11s)1394=== CONT TestPushWaitsForSweepHoldingRow13952026/11/01 17:56:08 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"13962026/11/01 17:56:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13972026/11/01 17:56:08 WARN Failed to register uploaded object key=hc0rps3qq7rmink5rzbl9v303gdbxmfc.ls error="server returned 404: 404 page not found\n"13982026/11/01 17:56:08 INFO Signed narinfos id=1 count=113992026/11/01 17:56:08 INFO Uploading 1 narinfos14002026/11/01 17:56:08 INFO Received complete push request method=POST path=/api/pushes/1/complete14012026/11/01 17:56:08 WARN Failed to register uploaded object key=hc0rps3qq7rmink5rzbl9v303gdbxmfc.narinfo error="server returned 404: 404 page not found\n"14022026/11/01 17:56:08 INFO Completed push id=1 objects=3 duration=27.809792ms14032026/11/01 17:56:08 INFO Upload complete. (260ms)1404=== NAME TestNARDeduplicationMetadataUploadBug1405 metadata_upload_test.go:54: Retrieved narinfo from S3:1406 StorePath: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestNARDeduplicationMetadataUploadBug3372347373/001/store/hc0rps3qq7rmink5rzbl9v303gdbxmfc-file1.txt1407 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1408 Compression: zstd1409 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1410 NarSize: 1601411 References: 1412 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1413 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1414 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1415 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1416 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/8/scratch/90a332d44a448eb6/build/TestNARDeduplicationMetadataUploadBug3372347373/001/store/59mvqn2h58a4309s8zn9ia6srhapzwix-file2.txt14172026/11/01 17:56:08 INFO Received push request method=POST path=/api/pushes14182026/11/01 17:56:08 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14192026/11/01 17:56:08 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14202026/11/01 17:56:08 WARN Failed to register uploaded object key=59mvqn2h58a4309s8zn9ia6srhapzwix.ls error="server returned 404: 404 page not found\n"14212026/11/01 17:56:08 INFO Signed narinfos id=2 count=114222026/11/01 17:56:08 INFO Uploading 1 narinfos1423=== CONT TestGCEndsOnShutdown1424=== RUN TestGCEndsOnShutdown/before_the_run1425--- PASS: TestPresentRefreshesOnlyStaleClosures (6.37s)1426=== PAUSE TestGCEndsOnShutdown/before_the_run1427=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1428=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1429=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1430=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1431=== CONT TestSweepRechecksPendingAfterLocking14322026/11/01 17:56:08 INFO Received complete push request method=POST path=/api/pushes/2/complete14332026/11/01 17:56:08 WARN Failed to register uploaded object key=59mvqn2h58a4309s8zn9ia6srhapzwix.narinfo error="server returned 404: 404 page not found\n"14342026/11/01 17:56:08 INFO Completed push id=2 objects=3 duration=1.303333ms14352026/11/01 17:56:08 INFO Upload complete. (184ms)1436=== NAME TestNARDeduplicationMetadataUploadBug1437 metadata_upload_test.go:76: Retrieved narinfo from S3:1438 StorePath: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestNARDeduplicationMetadataUploadBug3372347373/001/store/59mvqn2h58a4309s8zn9ia6srhapzwix-file2.txt1439 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1440 Compression: zstd1441 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1442 NarSize: 1601443 References: 1444 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1445 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1446 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1447 {"version":1,"root":{"type":"regular","size":44}}1448--- PASS: TestNARDeduplicationMetadataUploadBug (8.01s)1449=== CONT TestCommitRacingPendingCleanupKeepsObjects1450--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (7.82s)1451=== CONT TestGetExistingObjectsLocksRows14522026/11/01 17:56:09 WARN readiness check failed error="closed pool"1453--- PASS: TestService_readinessHandler (6.61s)1454=== CONT TestSweepSkipsRowsLockedByPush14552026/11/01 17:56:09 INFO Received uploads request method=POST path=/api/pending_closures14562026/11/01 17:56:09 INFO Received uploads request method=POST path=/api/pending_closures14572026/11/01 17:56:09 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14582026/11/01 17:56:09 INFO Uploading 7hcma03arhzh6zb1aiwjnigyq55p8qgm-shared-dep (136B)14592026/11/01 17:56:09 INFO Uploading qnfij695mcpnlzn270gzcbjj9klpx0km-b (256B)1460--- PASS: TestCacheStatsHandler (6.30s)1461=== CONT TestFailedS3DeleteKeepsTombstone14622026/11/01 17:56:09 WARN Failed to register uploaded object key=9sd7iazmdw0pj24yp3lys9d4cmjk2g1q.ls error="server returned 404: 404 page not found\n"14632026/11/01 17:56:09 WARN Failed to register uploaded object key=7hcma03arhzh6zb1aiwjnigyq55p8qgm.ls error="server returned 404: 404 page not found\n"14642026/11/01 17:56:09 WARN Failed to register uploaded object key=qnfij695mcpnlzn270gzcbjj9klpx0km.ls error="server returned 404: 404 page not found\n"14652026/11/01 17:56:09 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14662026/11/01 17:56:09 WARN Failed to register uploaded object key=nar/0hrsm749zwac9ri3p45wxqrc6yfry3d75y8jk43jp4vcg7cvdxgl.nar.zst error="server returned 404: 404 page not found\n"14672026/11/01 17:56:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14682026/11/01 17:56:09 INFO Signed narinfos id=2 count=214692026/11/01 17:56:09 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14702026/11/01 17:56:09 INFO Signed narinfos id=1 count=214712026/11/01 17:56:09 INFO Uploading 4 narinfos14722026/11/01 17:56:09 WARN Failed to register uploaded object key=7hcma03arhzh6zb1aiwjnigyq55p8qgm.narinfo error="server returned 404: 404 page not found\n"14732026/11/01 17:56:09 WARN Failed to register uploaded object key=qnfij695mcpnlzn270gzcbjj9klpx0km.narinfo error="server returned 404: 404 page not found\n"14742026/11/01 17:56:09 WARN Failed to register uploaded object key=9sd7iazmdw0pj24yp3lys9d4cmjk2g1q.narinfo error="server returned 404: 404 page not found\n"14752026/11/01 17:56:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14762026/11/01 17:56:09 WARN Failed to register uploaded object key=7hcma03arhzh6zb1aiwjnigyq55p8qgm.narinfo error="server returned 404: 404 page not found\n"14772026/11/01 17:56:09 INFO Completed upload id=1 objects=6 duration=27.613917ms14782026/11/01 17:56:09 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14792026/11/01 17:56:09 INFO Completed upload id=2 objects=6 duration=884.292µs14802026/11/01 17:56:09 INFO Upload complete. (427ms)1481=== NAME TestClientFallsBackToClosures1482 client_pushes_test.go:112: Retrieved narinfo from S3:1483 StorePath: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientFallsBackToClosures977013273/001/store/7hcma03arhzh6zb1aiwjnigyq55p8qgm-shared-dep1484 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1485 Compression: zstd1486 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821487 NarSize: 1361488 References: 1489 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1490 client_pushes_test.go:112: Retrieved narinfo from S3:1491 StorePath: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientFallsBackToClosures977013273/001/store/9sd7iazmdw0pj24yp3lys9d4cmjk2g1q-a1492 URL: nar/0hrsm749zwac9ri3p45wxqrc6yfry3d75y8jk43jp4vcg7cvdxgl.nar.zst1493 Compression: zstd1494 NarHash: sha256:0hrsm749zwac9ri3p45wxqrc6yfry3d75y8jk43jp4vcg7cvdxgl1495 NarSize: 2561496 References: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientFallsBackToClosures977013273/001/store/7hcma03arhzh6zb1aiwjnigyq55p8qgm-shared-dep1497 CA: text:sha256:0mgwc3lm9k183bb0iv2g5ddrqllgmi6pz9zm2ncv623np2a1i6yr1498--- PASS: TestService_healthCheckHandler (6.57s)1499=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1500=== NAME TestClientFallsBackToClosures1501 client_pushes_test.go:112: Retrieved narinfo from S3:1502 StorePath: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientFallsBackToClosures977013273/001/store/qnfij695mcpnlzn270gzcbjj9klpx0km-b1503 URL: nar/0hrsm749zwac9ri3p45wxqrc6yfry3d75y8jk43jp4vcg7cvdxgl.nar.zst1504 Compression: zstd1505 NarHash: sha256:0hrsm749zwac9ri3p45wxqrc6yfry3d75y8jk43jp4vcg7cvdxgl1506 NarSize: 2561507 References: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientFallsBackToClosures977013273/001/store/7hcma03arhzh6zb1aiwjnigyq55p8qgm-shared-dep1508 CA: text:sha256:0mgwc3lm9k183bb0iv2g5ddrqllgmi6pz9zm2ncv623np2a1i6yr1509--- PASS: TestClientFallsBackToClosures (7.36s)1510=== CONT TestForceGCDuringPushOffersSweptObject1511=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1512=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1513=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1514=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1515=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1516=== NAME TestClientCADerivations1517 client_ca_test.go:136: Built CA derivation: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientCADerivations3849799524/001/store/mhh33h2j3p1vrnz0j3q520550dxqaa3r-ca-test1518 client_ca_test.go:139: Found 1 dependencies (including self)15192026/11/01 17:56:11 INFO Received push request method=POST path=/api/pushes15202026/11/01 17:56:11 INFO Received push request method=POST path=/api/pushes15212026/11/01 17:56:11 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15222026/11/01 17:56:11 INFO Uploading mhh33h2j3p1vrnz0j3q520550dxqaa3r-ca-test (144B)15232026/11/01 17:56:11 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15242026/11/01 17:56:11 INFO Uploading bkpz3jm5mc2lkyrd30s5bamrwiv1cqyv-a (256B)15252026/11/01 17:56:11 INFO Uploading 5p5bfsijfsm3h9pq0xw5d59mnp4icpn5-shared-dep (136B)15262026/11/01 17:56:11 WARN Failed to register uploaded object key=mhh33h2j3p1vrnz0j3q520550dxqaa3r.ls error="server returned 404: 404 page not found\n"15272026/11/01 17:56:11 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"15282026/11/01 17:56:11 WARN Failed to register uploaded object key=3q56dsm2vlmhrigiyhd9rqb16jhj5r4h.ls error="server returned 404: 404 page not found\n"15292026/11/01 17:56:11 WARN Failed to register uploaded object key=log/xwhlklf2y6vcx216566lmgmksyli6n4z-ca-test.drv error="server returned 404: 404 page not found\n"15302026/11/01 17:56:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15312026/11/01 17:56:11 WARN Failed to register uploaded object key=bkpz3jm5mc2lkyrd30s5bamrwiv1cqyv.ls error="server returned 404: 404 page not found\n"15322026/11/01 17:56:11 INFO Signed narinfos id=1 count=115332026/11/01 17:56:11 WARN Failed to register uploaded object key=nar/0m44wx7kgspy41zkhh37146il1901b0yivqgfysv8y1gsbwnni8p.nar.zst error="server returned 404: 404 page not found\n"15342026/11/01 17:56:11 WARN Failed to register uploaded object key=5p5bfsijfsm3h9pq0xw5d59mnp4icpn5.ls error="server returned 404: 404 page not found\n"15352026/11/01 17:56:11 INFO Uploading 1 narinfos15362026/11/01 17:56:11 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15372026/11/01 17:56:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15382026/11/01 17:56:11 INFO Signed narinfos id=1 count=315392026/11/01 17:56:11 INFO Uploading 3 narinfos15402026/11/01 17:56:11 INFO Received complete push request method=POST path=/api/pushes/1/complete15412026/11/01 17:56:11 WARN Failed to register uploaded object key=mhh33h2j3p1vrnz0j3q520550dxqaa3r.narinfo error="server returned 404: 404 page not found\n"15422026/11/01 17:56:11 INFO Completed push id=1 objects=4 duration=32.0795ms15432026/11/01 17:56:11 INFO Upload complete. (381ms)15442026/11/01 17:56:11 WARN Failed to register uploaded object key=3q56dsm2vlmhrigiyhd9rqb16jhj5r4h.narinfo error="server returned 404: 404 page not found\n"1545 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientCADerivations3849799524/001/store/mhh33h2j3p1vrnz0j3q520550dxqaa3r-ca-test1546 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1547 Compression: zstd1548 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1549 NarSize: 1441550 References: 1551 Deriver: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientCADerivations3849799524/001/store/xwhlklf2y6vcx216566lmgmksyli6n4z-ca-test.drv15522026/11/01 17:56:11 WARN Failed to register uploaded object key=5p5bfsijfsm3h9pq0xw5d59mnp4icpn5.narinfo error="server returned 404: 404 page not found\n"1553 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n15542026/11/01 17:56:11 INFO Received complete push request method=POST path=/api/pushes/1/complete1555 client_ca_test.go:185: Checking for realisation files in S3...15562026/11/01 17:56:11 WARN Failed to register uploaded object key=bkpz3jm5mc2lkyrd30s5bamrwiv1cqyv.narinfo error="server returned 404: 404 page not found\n"1557 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1558 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache15592026/11/01 17:56:11 INFO Completed push id=1 objects=8 duration=31.614458ms15602026/11/01 17:56:11 INFO Upload complete. (369ms)1561=== NAME TestClientPushesUseOnePush1562 client_pushes_test.go:97: Retrieved narinfo from S3:1563 StorePath: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientPushesUseOnePush2512128736/001/store/5p5bfsijfsm3h9pq0xw5d59mnp4icpn5-shared-dep1564 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1565 Compression: zstd1566 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821567 NarSize: 1361568 References: 1569 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n15702026/11/01 17:56:11 INFO Received push request method=POST path=/api/pushes1571 client_pushes_test.go:97: Retrieved narinfo from S3:1572 StorePath: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientPushesUseOnePush2512128736/001/store/bkpz3jm5mc2lkyrd30s5bamrwiv1cqyv-a1573 URL: nar/0m44wx7kgspy41zkhh37146il1901b0yivqgfysv8y1gsbwnni8p.nar.zst1574 Compression: zstd1575 NarHash: sha256:0m44wx7kgspy41zkhh37146il1901b0yivqgfysv8y1gsbwnni8p1576 NarSize: 2561577 References: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientPushesUseOnePush2512128736/001/store/5p5bfsijfsm3h9pq0xw5d59mnp4icpn5-shared-dep1578 CA: text:sha256:086cawzfhb8w6wvrrzcizfp98kmjk2ira4g5ngxwyw721fvwsc1x1579 client_pushes_test.go:97: Retrieved narinfo from S3:1580 StorePath: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientPushesUseOnePush2512128736/001/store/3q56dsm2vlmhrigiyhd9rqb16jhj5r4h-b1581 URL: nar/0m44wx7kgspy41zkhh37146il1901b0yivqgfysv8y1gsbwnni8p.nar.zst1582 Compression: zstd1583 NarHash: sha256:0m44wx7kgspy41zkhh37146il1901b0yivqgfysv8y1gsbwnni8p1584 NarSize: 2561585 References: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientPushesUseOnePush2512128736/001/store/5p5bfsijfsm3h9pq0xw5d59mnp4icpn5-shared-dep1586 CA: text:sha256:086cawzfhb8w6wvrrzcizfp98kmjk2ira4g5ngxwyw721fvwsc1x15872026/11/01 17:56:11 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15882026/11/01 17:56:11 INFO Uploading z8g7w6kmlvhlg8b82j95rikbab87zlh3-shared-dep (136B)15892026/11/01 17:56:11 INFO Uploading 0x32r386dzfza14m0a0bya4vinx0bn92-top (264B)1590--- PASS: TestClientPushesUseOnePush (7.31s)1591=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed15922026/11/01 17:56:11 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15932026/11/01 17:56:11 WARN Failed to register uploaded object key=0x32r386dzfza14m0a0bya4vinx0bn92.ls error="server returned 404: 404 page not found\n"15942026/11/01 17:56:11 WARN Failed to register uploaded object key=z8g7w6kmlvhlg8b82j95rikbab87zlh3.ls error="server returned 404: 404 page not found\n"15952026/11/01 17:56:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15962026/11/01 17:56:11 WARN Failed to register uploaded object key=nar/0ldc2kvbfvmp74pdgnd53mschpgy2c66y2amdkpzz7syhrh6d716.nar.zst error="server returned 404: 404 page not found\n"15972026/11/01 17:56:11 INFO Signed narinfos id=1 count=215982026/11/01 17:56:11 INFO Uploading 2 narinfos1599--- PASS: TestService_ReadScope_PublicByDefault (6.49s)1600=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1601=== NAME TestClientCADerivations1602 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket70?endpoint=http://localhost:56012®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientCADerivations3849799524/001/store'1603 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 116042026/11/01 17:56:11 WARN Failed to register uploaded object key=z8g7w6kmlvhlg8b82j95rikbab87zlh3.narinfo error="server returned 404: 404 page not found\n"16052026/11/01 17:56:11 WARN Failed to register uploaded object key=0x32r386dzfza14m0a0bya4vinx0bn92.narinfo error="server returned 404: 404 page not found\n"16062026/11/01 17:56:11 INFO Received complete push request method=POST path=/api/pushes/1/complete16072026/11/01 17:56:11 INFO Completed push id=1 objects=6 duration=12.806458ms16082026/11/01 17:56:11 INFO Upload complete. (311ms)1609=== NAME TestClientSharedPathCommittedMidPush1610 client_integration_test.go:727: Retrieved narinfo from S3:1611 StorePath: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientSharedPathCommittedMidPush3084548526/001/store/z8g7w6kmlvhlg8b82j95rikbab87zlh3-shared-dep1612 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1613 Compression: zstd1614 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821615 NarSize: 1361616 References: 1617 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1618 client_integration_test.go:727: Retrieved narinfo from S3:1619 StorePath: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientSharedPathCommittedMidPush3084548526/001/store/0x32r386dzfza14m0a0bya4vinx0bn92-top1620 URL: nar/0ldc2kvbfvmp74pdgnd53mschpgy2c66y2amdkpzz7syhrh6d716.nar.zst1621 Compression: zstd1622 NarHash: sha256:0ldc2kvbfvmp74pdgnd53mschpgy2c66y2amdkpzz7syhrh6d7161623 NarSize: 2641624 References: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientSharedPathCommittedMidPush3084548526/001/store/z8g7w6kmlvhlg8b82j95rikbab87zlh3-shared-dep1625 CA: text:sha256:176xbvxw52lzbzcf67n5f44gbffc82kg3khrzfscf6c479yp8mlk1626--- PASS: TestClientCADerivations (7.99s)1627=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1628=== NAME TestPinProtectsFromGC1629 client_integration_test.go:778: Pinned store path: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestPinProtectsFromGC1261793938/001/store/k43rpy34idb3hp4gqh57w9b240p2rzrg-pinned-file.txt1630 client_integration_test.go:779: Unpinned store path: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestPinProtectsFromGC1261793938/001/store/cdffmr2hz2id52hgw00qac4fjzws2l2y-unpinned-file.txt1631=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1632--- PASS: TestClientSharedPathCommittedMidPush (6.72s)16332026/11/01 17:56:11 INFO Received push request method=POST path=/api/pushes16342026/11/01 17:56:11 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16352026/11/01 17:56:11 INFO Uploading k43rpy34idb3hp4gqh57w9b240p2rzrg-pinned-file.txt (128B)16362026/11/01 17:56:11 WARN Failed to register uploaded object key=k43rpy34idb3hp4gqh57w9b240p2rzrg.ls error="server returned 404: 404 page not found\n"16372026/11/01 17:56:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16382026/11/01 17:56:11 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16392026/11/01 17:56:11 INFO Signed narinfos id=1 count=116402026/11/01 17:56:11 INFO Uploading 1 narinfos16412026/11/01 17:56:11 INFO Received complete push request method=POST path=/api/pushes/1/complete16422026/11/01 17:56:11 WARN Failed to register uploaded object key=k43rpy34idb3hp4gqh57w9b240p2rzrg.narinfo error="server returned 404: 404 page not found\n"16432026/11/01 17:56:11 INFO Completed push id=1 objects=3 duration=61.749083ms16442026/11/01 17:56:11 INFO Upload complete. (298ms)16452026/11/01 17:56:12 INFO Received push request method=POST path=/api/pushes16462026/11/01 17:56:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16472026/11/01 17:56:12 INFO Uploading cdffmr2hz2id52hgw00qac4fjzws2l2y-unpinned-file.txt (128B)16482026/11/01 17:56:12 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16492026/11/01 17:56:12 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16502026/11/01 17:56:12 WARN Failed to register uploaded object key=cdffmr2hz2id52hgw00qac4fjzws2l2y.ls error="server returned 404: 404 page not found\n"16512026/11/01 17:56:12 INFO Signed narinfos id=2 count=116522026/11/01 17:56:12 INFO Uploading 1 narinfos1653=== RUN TestService_RequireScope_OIDC/builder_may_write1654=== PAUSE TestService_RequireScope_OIDC/builder_may_write1655=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1656=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1657=== RUN TestService_RequireScope_OIDC/ops_may_admin1658=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1659=== RUN TestService_RequireScope_OIDC/ops_may_not_write1660=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1661=== RUN TestService_RequireScope_OIDC/reader_may_not_write1662=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1663=== RUN TestService_RequireScope_OIDC/static_token_may_admin1664=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1665=== RUN TestService_RequireScope_OIDC/static_token_may_write1666=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1667=== RUN TestService_RequireScope_OIDC/reader_may_read1668=== PAUSE TestService_RequireScope_OIDC/reader_may_read1669=== RUN TestService_RequireScope_OIDC/writer_implies_read1670=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1671=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1672=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1673=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1674=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1675=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1676=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1677=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1678=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1679=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1680=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1681=== CONT TestPush_RejectsBadRequests/no_roots16822026/11/01 17:56:12 INFO Received complete push request method=POST path=/api/pushes/2/complete16832026/11/01 17:56:12 INFO Received push request method=POST path=/api/pushes16842026/11/01 17:56:12 WARN Failed to register uploaded object key=cdffmr2hz2id52hgw00qac4fjzws2l2y.narinfo error="server returned 404: 404 page not found\n"1685=== CONT TestPush_RejectsBadRequests/bad_root16862026/11/01 17:56:12 INFO Completed push id=2 objects=3 duration=811.75µs16872026/11/01 17:56:12 INFO Received push request method=POST path=/api/pushes1688=== CONT TestPush_RejectsBadRequests/root_not_in_objects16892026/11/01 17:56:12 INFO Upload complete. (203ms)16902026/11/01 17:56:12 INFO Received push request method=POST path=/api/pushes1691=== CONT TestPush_RejectsBadRequests/no_objects16922026/11/01 17:56:12 INFO Received push request method=POST path=/api/pushes1693=== CONT TestServerTLSConfig/no_client_CA1694=== CONT TestServerTLSConfig/not_a_PEM_file1695--- PASS: TestPush_RejectsBadRequests (7.77s)1696 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1697 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1698 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1699 --- PASS: TestPush_RejectsBadRequests/no_objects (0.01s)1700=== CONT TestServerTLSConfig/missing_CA_file1701--- PASS: TestServerTLSConfig (0.01s)1702 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1703 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)1704 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1705=== CONT TestIsValidCachePath/narinfo1706=== CONT TestIsValidCachePath/index.html1707=== CONT TestIsValidCachePath/short_hash1708=== CONT TestIsValidCachePath/wrong_extension1709=== CONT TestIsValidCachePath/leading_slash1710=== CONT TestIsValidCachePath/empty1711=== CONT TestIsValidCachePath/random_path1712=== CONT TestIsValidCachePath/invalid_char_u1713=== CONT TestIsValidCachePath/invalid_char_e1714=== CONT TestIsValidCachePath/traversal_in_middle1715=== CONT TestIsValidCachePath/traversal_parent1716=== CONT TestIsValidCachePath/nar_uncompressed1717=== CONT TestIsValidCachePath/log1718=== CONT TestIsValidCachePath/realisation1719=== CONT TestIsValidCachePath/nix-cache-info1720=== CONT TestIsValidCachePath/ls1721=== CONT TestIsValidCachePath/nar_xz1722=== CONT TestIsValidCachePath/nar_zst1723=== CONT TestIsValidCachePath/nar_bz21724=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1725--- PASS: TestIsValidCachePath (0.01s)1726 --- PASS: TestIsValidCachePath/narinfo (0.00s)1727 --- PASS: TestIsValidCachePath/index.html (0.00s)1728 --- PASS: TestIsValidCachePath/short_hash (0.00s)1729 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1730 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1731 --- PASS: TestIsValidCachePath/empty (0.00s)1732 --- PASS: TestIsValidCachePath/random_path (0.00s)1733 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1734 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1735 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1736 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1737 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1738 --- PASS: TestIsValidCachePath/log (0.00s)1739 --- PASS: TestIsValidCachePath/realisation (0.00s)1740 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1741 --- PASS: TestIsValidCachePath/ls (0.00s)1742 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1743 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1744 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1745 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1746=== CONT TestParseSingleRange/none1747=== CONT TestResolveDBConnectionString/flag_wins1748=== CONT TestParseSingleRange/start_far_past_EOF1749=== CONT TestParseSingleRange/start_past_EOF1750=== CONT TestParseSingleRange/single_byte1751=== CONT TestParseSingleRange/suffix_exceeds_size1752=== CONT TestParseSingleRange/suffix17532026/11/01 17:56:12 INFO Starting cleanup of old closures method=DELETE path=/api/closures1754=== CONT TestParseSingleRange/end_clamped_to_size1755=== CONT TestParseSingleRange/open-ended1756=== CONT TestParseSingleRange/closed1757=== CONT TestParseSingleRange/malformed_end_before_start1758=== CONT TestParseSingleRange/malformed_both_empty1759=== CONT TestParseSingleRange/malformed_no_dash1760=== CONT TestParseSingleRange/multi-range_ignored1761=== CONT TestParseSingleRange/unknown_unit1762--- PASS: TestParseSingleRange (0.00s)1763 --- PASS: TestParseSingleRange/none (0.00s)1764 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1765 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1766 --- PASS: TestParseSingleRange/single_byte (0.00s)1767 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1768 --- PASS: TestParseSingleRange/suffix (0.00s)1769 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1770 --- PASS: TestParseSingleRange/open-ended (0.00s)1771 --- PASS: TestParseSingleRange/closed (0.00s)1772 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1773 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1774 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1775 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1776 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1777=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale17782026/11/01 17:56:12 INFO Garbage collection started17792026/11/01 17:56:12 INFO Aborted multipart uploads count=0 kept=017802026/11/01 17:56:12 WARN Force mode enabled - objects will be deleted immediately without grace period1781=== NAME TestClientWithDependencies1782 client_integration_test.go:660: Built derivation: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientWithDependencies2610406114/001/store/r51xzrzqyba5aq0va64kmny97wmf073h-test-script1783 client_integration_test.go:662: Found 1 dependencies (including self)17842026/11/01 17:56:12 INFO Received push request method=POST path=/api/pushes17852026/11/01 17:56:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17862026/11/01 17:56:12 INFO Uploading r51xzrzqyba5aq0va64kmny97wmf073h-test-script (136B)17872026/11/01 17:56:12 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=017882026/11/01 17:56:12 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17892026/11/01 17:56:12 WARN Failed to register uploaded object key=r51xzrzqyba5aq0va64kmny97wmf073h.ls error="server returned 404: 404 page not found\n"17902026/11/01 17:56:12 INFO Vacuumed table table=pending_closures17912026/11/01 17:56:12 WARN Failed to register uploaded object key=log/06kqa0l5k0n8gy8bi4vnlb9rpi6prlyr-test-script.drv error="server returned 404: 404 page not found\n"17922026/11/01 17:56:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17932026/11/01 17:56:12 INFO Signed narinfos id=1 count=117942026/11/01 17:56:12 INFO Uploading 1 narinfos17952026/11/01 17:56:12 INFO Vacuumed table table=pending_objects17962026/11/01 17:56:12 INFO Vacuumed table table=multipart_uploads17972026/11/01 17:56:12 INFO Received complete push request method=POST path=/api/pushes/1/complete17982026/11/01 17:56:12 WARN Failed to register uploaded object key=r51xzrzqyba5aq0va64kmny97wmf073h.narinfo error="server returned 404: 404 page not found\n"17992026/11/01 17:56:12 INFO Vacuumed table table=closures18002026/11/01 17:56:12 INFO Completed push id=1 objects=4 duration=32.638084ms18012026/11/01 17:56:12 INFO Upload complete. (359ms)1802 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientWithDependencies2610406114/001/store) requires matching store prefix18032026/11/01 17:56:12 INFO Vacuumed table table=objects1804=== NAME TestClientMultipleUploads1805 client_integration_test.go:405: Created store path 0: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientMultipleUploads3551493716/001/store/f3ka81kkvilbainj40wrwvw05qp0pfbn-test-file-0.txt1806--- PASS: TestClientWithDependencies (7.62s)1807=== CONT TestResolveDBConnectionString/nothing_configured1808=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1809=== CONT TestResolveDBConnectionString/missing_file_is_an_error1810=== CONT TestResolveDBConnectionString/file_when_flag_empty1811=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1812--- PASS: TestResolveDBConnectionString (0.00s)1813 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1814 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1815 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1816 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1817 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1818=== NAME TestClientMultipleUploads1819 client_integration_test.go:405: Created store path 1: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientMultipleUploads3551493716/001/store/6sns7qh88cpb5rrd3ddf9c45llanjy43-test-file-1.txt1820 client_integration_test.go:405: Created store path 2: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientMultipleUploads3551493716/001/store/jipvz3s72wdhh19lxym6yxmjcj7ifr1a-test-file-2.txt1821=== NAME TestClientIntegration1822 client_integration_test.go:291: Created store path: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientIntegration3007912873/002/store/rk8sqdahmwdx1gqq0ya3b1fimn9llxn5-test-file.txt1823=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1824=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1825=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1826=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1827=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1828=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1829=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1830=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1831=== CONT TestIsValidUploadKey/narinfo1832=== CONT TestIsValidUploadKey/realisation_plus_in_output1833=== CONT TestIsValidUploadKey/unknown_type1834=== CONT TestIsValidUploadKey/empty_key1835=== CONT TestIsValidUploadKey/absolute1836=== CONT TestIsValidUploadKey/traversal_nar1837=== CONT TestIsValidUploadKey/traversal1838=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1839=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1840=== CONT TestIsValidUploadKey/nix-cache-info1841=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1842=== CONT TestIsValidUploadKey/build_log_home-manager_file1843=== CONT TestIsValidUploadKey/realisation1844=== CONT TestIsValidUploadKey/index.html1845=== CONT TestIsValidUploadKey/build_log_equals1846=== CONT TestIsValidUploadKey/build_log_question_mark1847=== CONT TestIsValidUploadKey/build_log_plus_in_name1848=== CONT TestIsValidUploadKey/nar_plain1849=== CONT TestIsValidUploadKey/nar_xz1850=== CONT TestIsValidUploadKey/build_log1851=== CONT TestIsValidUploadKey/listing1852=== CONT TestIsValidUploadKey/nar_zst1853--- PASS: TestIsValidUploadKey (0.04s)1854 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1855 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1856 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1857 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1858 --- PASS: TestIsValidUploadKey/absolute (0.00s)1859 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1860 --- PASS: TestIsValidUploadKey/traversal (0.00s)1861 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1862 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1863 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1864 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1865 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1866 --- PASS: TestIsValidUploadKey/realisation (0.00s)1867 --- PASS: TestIsValidUploadKey/index.html (0.00s)1868 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1869 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1870 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1871 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1872 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1873 --- PASS: TestIsValidUploadKey/build_log (0.00s)1874 --- PASS: TestIsValidUploadKey/listing (0.00s)1875 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1876=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18772026/11/01 17:56:13 INFO Received uploads request method=POST path=/18782026/11/01 17:56:13 INFO Received push request method=POST path=/api/pushes18792026/11/01 17:56:13 INFO Received push request method=POST path=/api/pushes18802026/11/01 17:56:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18812026/11/01 17:56:13 INFO Uploading rk8sqdahmwdx1gqq0ya3b1fimn9llxn5-test-file.txt (152B)18822026/11/01 17:56:13 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18832026/11/01 17:56:13 INFO Uploading f3ka81kkvilbainj40wrwvw05qp0pfbn-test-file-0.txt (160B)18842026/11/01 17:56:13 INFO Uploading 6sns7qh88cpb5rrd3ddf9c45llanjy43-test-file-1.txt (160B)18852026/11/01 17:56:13 INFO Uploading jipvz3s72wdhh19lxym6yxmjcj7ifr1a-test-file-2.txt (160B)18862026/11/01 17:56:13 WARN Failed to register uploaded object key=rk8sqdahmwdx1gqq0ya3b1fimn9llxn5.ls error="server returned 404: 404 page not found\n"18872026/11/01 17:56:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18882026/11/01 17:56:13 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18892026/11/01 17:56:13 INFO Signed narinfos id=1 count=118902026/11/01 17:56:13 WARN Failed to register uploaded object key=6sns7qh88cpb5rrd3ddf9c45llanjy43.ls error="server returned 404: 404 page not found\n"18912026/11/01 17:56:13 INFO Uploading 1 narinfos18922026/11/01 17:56:13 WARN Failed to register uploaded object key=f3ka81kkvilbainj40wrwvw05qp0pfbn.ls error="server returned 404: 404 page not found\n"18932026/11/01 17:56:13 WARN Failed to register uploaded object key=jipvz3s72wdhh19lxym6yxmjcj7ifr1a.ls error="server returned 404: 404 page not found\n"18942026/11/01 17:56:13 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18952026/11/01 17:56:13 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18962026/11/01 17:56:13 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18972026/11/01 17:56:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1898--- PASS: TestDeleteClosuresRacingPins (11.61s)18992026/11/01 17:56:13 INFO Signed narinfos id=1 count=31900=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19012026/11/01 17:56:13 INFO Received request for more parts method=POST path=/19022026/11/01 17:56:13 INFO Uploading 3 narinfos19032026/11/01 17:56:13 INFO Received complete push request method=POST path=/api/pushes/1/complete19042026/11/01 17:56:13 WARN Failed to register uploaded object key=rk8sqdahmwdx1gqq0ya3b1fimn9llxn5.narinfo error="server returned 404: 404 page not found\n"1905=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19062026/11/01 17:56:13 INFO Received complete multipart upload request method=POST path=/19072026/11/01 17:56:13 INFO Completed push id=1 objects=3 duration=12.410375ms19082026/11/01 17:56:13 INFO Upload complete. (253ms)19092026/11/01 17:56:13 WARN Failed to register uploaded object key=jipvz3s72wdhh19lxym6yxmjcj7ifr1a.narinfo error="server returned 404: 404 page not found\n"19102026/11/01 17:56:13 WARN Failed to register uploaded object key=6sns7qh88cpb5rrd3ddf9c45llanjy43.narinfo error="server returned 404: 404 page not found\n"1911=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19122026/11/01 17:56:13 INFO Received uploads request method=POST path=/1913=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19142026/11/01 17:56:13 INFO Received complete multipart upload request method=POST path=/1915=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19162026/11/01 17:56:13 INFO Received request for more parts method=POST path=/1917=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19182026/11/01 17:56:13 INFO Received uploads request method=POST path=/1919--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1920 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1921 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1922 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1923 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1924=== CONT TestCacheConfigHandler/full_config,_no_issuer1925=== CONT TestCacheConfigHandler/no_signing_keys1926=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1927=== CONT TestCacheConfigHandler/no_cache_url_configured1928--- PASS: TestCacheConfigHandler (0.00s)1929 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1930 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1931 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1932 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1933=== CONT TestClientErrorHandling/InvalidStorePath19342026/11/01 17:56:13 INFO Received complete push request method=POST path=/api/pushes/1/complete19352026/11/01 17:56:13 WARN Failed to register uploaded object key=f3ka81kkvilbainj40wrwvw05qp0pfbn.narinfo error="server returned 404: 404 page not found\n"19362026/11/01 17:56:13 INFO Completed push id=1 objects=9 duration=20.277ms19372026/11/01 17:56:13 INFO Upload complete. (322ms)1938=== NAME TestClientMultipleUploads1939 client_integration_test.go:416: Uploaded 3 paths in 361.098042ms19402026/11/01 17:56:13 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19412026/11/01 17:56:13 WARN mTLS auth: bound subjects configured but subject DN unavailable19422026/11/01 17:56:13 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1943--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.55s)1944=== CONT TestClientErrorHandling/ServerNotAvailable19452026/11/01 17:56:13 INFO All 1 paths already cached1946=== NAME TestClientIntegration1947 client_integration_test.go:317: Retrieved narinfo from S3:1948 StorePath: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestClientIntegration3007912873/002/store/rk8sqdahmwdx1gqq0ya3b1fimn9llxn5-test-file.txt1949 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1950 Compression: zstd1951 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11952 NarSize: 1521953 References: 1954 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11955 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1956 client_integration_test.go:318: Decompressed .ls content (64 bytes):1957 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1958--- PASS: TestClientMultipleUploads (7.47s)1959=== CONT TestClientErrorHandling/InvalidAuthToken1960--- PASS: TestUploadHandlersRejectOversizedBody (0.11s)1961 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1962 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)1963 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.39s)1964=== CONT TestPendingClosureWriteTimeout/empty1965=== CONT TestPendingClosureWriteTimeout/670k_objects1966=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1967--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.82s)1968=== CONT TestPendingClosureWriteTimeout/400_objects1969=== CONT TestProxyWriteTimeout/narinfo1970=== CONT TestProxyWriteTimeout/10_GiB_nar1971=== CONT TestProxyWriteTimeout/unknown_size1972=== CONT TestProxyWriteTimeout/1_GiB_nar1973--- PASS: TestProxyWriteTimeout (0.00s)1974 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1975 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1976 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1977 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1978=== CONT TestGCEndsOnShutdown/before_the_run19792026/11/01 17:56:13 INFO Received push request method=POST path=/api/pushes19802026/11/01 17:56:13 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/present19812026/11/01 17:56:13 INFO Object in database but missing from S3 key=rk8sqdahmwdx1gqq0ya3b1fimn9llxn5.ls19822026/11/01 17:56:13 WARN Found objects in DB but missing from S3, will re-upload count=119832026/11/01 17:56:13 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19842026/11/01 17:56:13 WARN Request failed, retrying attempt=2 backoff=202.103377ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19852026/11/01 17:56:14 INFO Received complete push request method=POST path=/api/pushes/2/complete19862026/11/01 17:56:14 WARN Failed to register uploaded object key=rk8sqdahmwdx1gqq0ya3b1fimn9llxn5.ls error="server returned 404: 404 page not found\n"19872026/11/01 17:56:14 INFO Completed push id=2 objects=3 duration=1.155917ms19882026/11/01 17:56:14 INFO Upload complete. (191ms)1989=== NAME TestClientIntegration1990 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1991 client_integration_test.go:335: Decompressed .ls content (49 bytes):1992 {"version":1,"root":{"type":"regular","size":39}}19932026/11/01 17:56:14 WARN Request failed, retrying attempt=3 backoff=417.586292ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1994--- PASS: TestService_ReadAuthMiddleware (6.85s)1995=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19962026/11/01 17:56:14 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=019972026/11/01 17:56:14 INFO Received create pin request method=POST path=/api/pins/myapp19982026/11/01 17:56:14 INFO Created/updated pin name=myapp store_path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestPinProtectsFromGC1261793938/001/store/k43rpy34idb3hp4gqh57w9b240p2rzrg-pinned-file.txt narinfo_key=k43rpy34idb3hp4gqh57w9b240p2rzrg.narinfo19992026/11/01 17:56:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures20002026/11/01 17:56:14 INFO Garbage collection started20012026/11/01 17:56:14 INFO Aborted multipart uploads count=0 kept=020022026/11/01 17:56:14 WARN Force mode enabled - objects will be deleted immediately without grace period20032026/11/01 17:56:14 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=020042026/11/01 17:56:14 INFO Vacuumed table table=pending_closures20052026/11/01 17:56:14 INFO Vacuumed table table=pending_objects20062026/11/01 17:56:14 INFO Vacuumed table table=multipart_uploads20072026/11/01 17:56:14 INFO Vacuumed table table=closures20082026/11/01 17:56:14 INFO Received push request method=POST path=/api/pushes20092026/11/01 17:56:14 INFO Vacuumed table table=objects20102026/11/01 17:56:14 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20112026/11/01 17:56:14 INFO Received complete push request method=POST path=/api/pushes/3/complete20122026/11/01 17:56:14 WARN Failed to register uploaded object key=rk8sqdahmwdx1gqq0ya3b1fimn9llxn5.ls error="server returned 404: 404 page not found\n"20132026/11/01 17:56:14 INFO Completed push id=3 objects=3 duration=1.557ms20142026/11/01 17:56:14 INFO Upload complete. (140ms)2015=== NAME TestClientIntegration2016 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)2017 client_integration_test.go:352: Decompressed .ls content (49 bytes):2018 {"version":1,"root":{"type":"regular","size":39}}2019 client_integration_test.go:363: Testing garbage collection...20202026/11/01 17:56:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures20212026/11/01 17:56:14 INFO Garbage collection started20222026/11/01 17:56:14 INFO Aborted multipart uploads count=0 kept=020232026/11/01 17:56:14 WARN Force mode enabled - objects will be deleted immediately without grace period2024--- PASS: TestRegisterCompletedObjectNeedsPendingRow (6.77s)2025=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark20262026/11/01 17:56:14 WARN Request failed, retrying attempt=4 backoff=737.034513ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20272026/11/01 17:56:14 INFO Received uploads request method=POST path=/api/pending_closures20282026/11/01 17:56:15 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=020292026/11/01 17:56:15 INFO Vacuumed table table=pending_closures20302026/11/01 17:56:15 INFO Vacuumed table table=pending_objects20312026/11/01 17:56:15 INFO Vacuumed table table=multipart_uploads20322026/11/01 17:56:15 INFO Vacuumed table table=closures20332026/11/01 17:56:15 INFO Vacuumed table table=objects20342026/11/01 17:56:15 WARN Request failed, retrying attempt=5 backoff=1.751475124s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20352026/11/01 17:56:15 INFO Aborted multipart uploads count=0 kept=02036--- PASS: TestPushWaitsForSweepHoldingRow (7.32s)2037=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows20382026/11/01 17:56:15 WARN Force mode enabled - objects will be deleted immediately without grace period20392026/11/01 17:56:15 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=020402026/11/01 17:56:15 INFO Vacuumed table table=pending_closures20412026/11/01 17:56:15 INFO Vacuumed table table=pending_objects20422026/11/01 17:56:15 INFO Vacuumed table table=multipart_uploads20432026/11/01 17:56:15 INFO Vacuumed table table=closures20442026/11/01 17:56:15 INFO Vacuumed table table=objects2045--- PASS: TestSweepRechecksPendingAfterLocking (7.08s)2046=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check20472026/11/01 17:56:15 INFO Aborted multipart uploads count=0 kept=020482026/11/01 17:56:15 WARN Force mode enabled - objects will be deleted immediately without grace period20492026/11/01 17:56:15 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/11/01 17:56:15 INFO Vacuumed table table=pending_closures20512026/11/01 17:56:16 INFO Vacuumed table table=pending_objects20522026/11/01 17:56:16 INFO Vacuumed table table=multipart_uploads20532026/11/01 17:56:16 INFO Vacuumed table table=closures20542026/11/01 17:56:16 INFO Vacuumed table table=objects2055--- PASS: TestCommitRacingPendingCleanupKeepsObjects (7.43s)2056=== CONT TestService_RequireScope_OIDC/builder_may_write2057=== CONT TestService_RequireScope_OIDC/reader_may_read2058=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2059=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20602026/11/01 17:56:16 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]2061=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2062=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2063=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2064=== CONT TestService_RequireScope_OIDC/writer_implies_read2065=== CONT TestService_RequireScope_OIDC/reader_may_not_write2066=== CONT TestService_RequireScope_OIDC/static_token_may_write2067=== CONT TestService_RequireScope_OIDC/static_token_may_admin2068=== CONT TestService_RequireScope_OIDC/ops_may_not_write2069--- PASS: TestGetExistingObjectsLocksRows (6.97s)2070=== CONT TestService_RequireScope_OIDC/ops_may_admin2071=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2072=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2073=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20742026/11/01 17:56:16 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]2075=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2076=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured20772026/11/01 17:56:16 WARN Authentication failed token_preview=eyJhbGciOi...A-5NMtbO7g token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2078--- PASS: TestService_RequireScope_OIDC (6.53s)2079 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2080 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2081 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2082 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.01s)2083 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2084 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2085 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2086 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2087 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2088 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2089 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2090 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2091 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2092 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2093--- PASS: TestService_AuthMiddleware_OIDC (6.60s)2094 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2095 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2096 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2097 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2098=== NAME TestPinProtectsFromGC2099 client_integration_test.go:887: Pin successfully protected closure from garbage collection2100--- PASS: TestPinProtectsFromGC (11.73s)21012026/11/01 17:56:16 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02102=== NAME TestClientIntegration2103 client_integration_test.go:370: Objects in database after GC:2104 client_integration_test.go:370: Successfully deleted all objects with GC --force21052026/11/01 17:56:16 INFO Aborted multipart uploads count=0 kept=021062026/11/01 17:56:16 WARN Force mode enabled - objects will be deleted immediately without grace period21072026/11/01 17:56:16 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=021082026/11/01 17:56:16 INFO Vacuumed table table=pending_closures21092026/11/01 17:56:16 INFO Vacuumed table table=pending_objects2110--- PASS: TestClientIntegration (10.08s)21112026/11/01 17:56:16 INFO Vacuumed table table=multipart_uploads21122026/11/01 17:56:16 INFO Vacuumed table table=closures21132026/11/01 17:56:16 INFO Vacuumed table table=objects21142026/11/01 17:56:16 INFO Aborted multipart uploads count=0 kept=021152026/11/01 17:56:16 WARN Force mode enabled - objects will be deleted immediately without grace period21162026/11/01 17:56:16 INFO Received uploads request method=POST path=/api/pending_closures21172026/11/01 17:56:16 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=021182026/11/01 17:56:16 INFO Vacuumed table table=pending_closures21192026/11/01 17:56:16 INFO Vacuumed table table=pending_objects21202026/11/01 17:56:16 INFO Vacuumed table table=multipart_uploads21212026/11/01 17:56:16 INFO Vacuumed table table=closures21222026/11/01 17:56:16 INFO Vacuumed table table=objects2123--- PASS: TestSweepSkipsRowsLockedByPush (7.80s)21242026/11/01 17:56:17 INFO Received uploads request method=POST path=/api/pending_closures21252026/11/01 17:56:17 INFO Aborted multipart uploads count=0 kept=021262026/11/01 17:56:17 WARN Force mode enabled - objects will be deleted immediately without grace period21272026/11/01 17:56:17 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."21282026/11/01 17:56:17 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."2129--- PASS: TestFailedS3DeleteKeepsTombstone (7.59s)21302026/11/01 17:56:17 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-config21312026/11/01 17:56:17 WARN Request failed, retrying attempt=2 backoff=184.119271ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21322026/11/01 17:56:17 INFO Received uploads request method=POST path=/api/pending_closures21332026/11/01 17:56:17 WARN Request failed, retrying attempt=3 backoff=396.46743ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2134--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.75s)21352026/11/01 17:56:17 INFO Received uploads request method=POST path=/api/pending_closures21362026/11/01 17:56:17 WARN Request failed, retrying attempt=4 backoff=733.786208ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21372026/11/01 17:56:18 INFO Received uploads request method=POST path=/api/pending_closures21382026/11/01 17:56:18 WARN Request failed, retrying attempt=5 backoff=1.596866703s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21392026/11/01 17:56:19 INFO Received uploads request method=POST path=/api/pending_closures21402026/11/01 17:56:20 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"21412026/11/01 17:56:20 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-config21422026/11/01 17:56:20 WARN Request failed, retrying attempt=2 backoff=187.205311ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21432026/11/01 17:56:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21442026/11/01 17:56:20 WARN Request failed, retrying attempt=3 backoff=386.167859ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21452026/11/01 17:56:20 INFO Received uploads request method=POST path=/api/pending_closures21462026/11/01 17:56:20 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLmZlODI4M2EyLTMwNzYtNGNkZi04YjkwLWI4MzFjMjFjMDM1ZngxNzkzNTU1Nzc3MTg5NjgyMDAw parts=1021472026/11/01 17:56:20 WARN Request failed, retrying attempt=4 backoff=798.089338ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21482026/11/01 17:56:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21492026/11/01 17:56:21 INFO Completed upload id=1 objects=3 duration=29.448083ms21502026/11/01 17:56:21 WARN Request failed, retrying attempt=5 backoff=1.509577437s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21512026/11/01 17:56:22 INFO Received uploads request method=POST path=/api/pending_closures21522026/11/01 17:56:22 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21532026/11/01 17:56:22 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21542026/11/01 17:56:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21552026/11/01 17:56:22 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLjJiN2UwMWRhLWY3ZTUtNDdjZi1iZjQ1LTc0MWQ3ZjhmNGVkYXgxNzkzNTU1Nzc3NzYyMjI0MDAw parts=1021562026/11/01 17:56:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21572026/11/01 17:56:22 INFO Completed upload id=1 objects=3 duration=21.557125ms21582026/11/01 17:56:22 INFO Received uploads request method=POST path=/api/pending_closures21592026/11/01 17:56:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21602026/11/01 17:56:23 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLjhkYzNjNGFjLTU4MjQtNDE0Ni04NmZiLWY5YmM4Mzk4OGI3OXgxNzkzNTU1Nzc4NjE3MDM2MDAw parts=102161=== NAME TestOrphanedObjectsGCStressTest2162 orphaned_objects_gc_test.go:503: Stress test completed successfully:2163 orphaned_objects_gc_test.go:504: - Active objects preserved: 202164 orphaned_objects_gc_test.go:505: - Objects deleted: 2102165 orphaned_objects_gc_test.go:506: - Total GC'd: 2102166--- PASS: TestOrphanedObjectsGCStressTest (35.42s)21672026/11/01 17:56:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21682026/11/01 17:56:23 INFO Completed upload id=1 objects=3 duration=18.1885ms21692026/11/01 17:56:23 INFO Received uploads request method=POST path=/api/pending_closures21702026/11/01 17:56:23 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_closures21712026/11/01 17:56:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2172--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2173 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (9.92s)2174 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (10.33s)21752026/11/01 17:56:23 WARN Request failed, retrying attempt=2 backoff=188.333836ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21762026/11/01 17:56:23 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLmVkMjc2NmVhLTlhN2YtNGVlOS1iNDEyLWExZmE4MTE3Y2M4OHgxNzkzNTU1Nzc5NjM4OTMyMDAw parts=1021772026/11/01 17:56:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21782026/11/01 17:56:23 INFO Completed upload id=1 objects=3 duration=17.567375ms21792026/11/01 17:56:23 INFO Received uploads request method=POST path=/api/pending_closures21802026/11/01 17:56:23 WARN Request failed, retrying attempt=3 backoff=375.572864ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21812026/11/01 17:56:23 INFO Received uploads request method=POST path=/api/pending_closures21822026/11/01 17:56:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21832026/11/01 17:56:23 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLmZjNjYwZjZkLTNhZTctNDE4My1hMzkxLWRjNTc4MjU4OGI1ZXgxNzkzNTU1NzgwNjk1NjY4MDAw parts=1021842026/11/01 17:56:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21852026/11/01 17:56:23 INFO Completed upload id=1 objects=3 duration=6.524583ms21862026/11/01 17:56:23 WARN Request failed, retrying attempt=4 backoff=765.31747ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21872026/11/01 17:56:24 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21882026/11/01 17:56:24 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21892026/11/01 17:56:24 INFO Received uploads request method=POST path=/api/pending_closures21902026/11/01 17:56:24 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21912026/11/01 17:56:24 WARN Found objects in DB but missing from S3, will re-upload count=121922026/11/01 17:56:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21932026/11/01 17:56:24 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLmEyMDUyZGI0LWQzNTEtNGJkMi04ZjFiLWJjMDE0NWM3ZjdmMHgxNzkzNTU1NzgyNTc0NjI1MDAw parts=1021942026/11/01 17:56:24 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21952026/11/01 17:56:24 INFO Completed upload id=2 objects=3 duration=374.708µs21962026/11/01 17:56:24 INFO Aborted multipart uploads count=0 kept=021972026/11/01 17:56:24 WARN Force mode enabled - objects will be deleted immediately without grace period2198--- PASS: TestPendingClosureWriteTimeout (0.00s)2199 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2200 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2201 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2202 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (10.75s)22032026/11/01 17:56:24 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:56012/bucket102/?delete=\": context canceled"22042026/11/01 17:56:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22052026/11/01 17:56:24 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=ZDY4MGZiYmMtMzdmNy00ZDNjLTkwOTEtYjk2ZmI1YWQ3MWMzLmZhZGM5MDRiLTc2NTUtNDllNy1iMzg5LTk2ZTdkYTAyZmNiNHgxNzkzNTU1NzgzMjM5NTQ3MDAw parts=1022062026/11/01 17:56:24 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22072026/11/01 17:56:24 INFO Completed upload id=2 objects=3 duration=1.291875ms22082026/11/01 17:56:24 INFO Received uploads request method=POST path=/api/pending_closures22092026/11/01 17:56:24 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22102026/11/01 17:56:24 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo22112026/11/01 17:56:24 INFO Aborted multipart uploads count=0 kept=022122026/11/01 17:56:24 WARN Force mode enabled - objects will be deleted immediately without grace period22132026-11-01 17:56:24.745 UTC [37506] ERROR: canceling statement due to user request22142026-11-01 17:56:24.745 UTC [37506] STATEMENT: -- name: MarkStaleObjects :execrows2215 WITH RECURSIVE ct AS (2216 SELECT timezone('UTC', now()) AS now2217 ),2218 closure_reach AS (2219 -- Start with all closure keys2220 SELECT o.key, o.refs2221 FROM objects o2222 INNER JOIN closures c ON o.key = c.key2223 UNION2224 -- Recursively add all referenced objects2225 SELECT o.key, o.refs2226 FROM objects o2227 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2228 ),2229 reachable_objects AS (2230 SELECT DISTINCT key FROM closure_reach2231 ),2232 stale_objects AS (2233 SELECT o.key2234 FROM objects AS o, ct2235 WHERE2236 NOT EXISTS (2237 SELECT 12238 FROM reachable_objects ro2239 WHERE ro.key = o.key2240 )2241 AND NOT EXISTS (2242 SELECT 12243 FROM pending_objects AS po2244 WHERE po.key = o.key2245 )2246 AND o.deleted_at IS NULL -- Only mark fresh objects2247 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2248 FOR UPDATE2249 )2250 UPDATE objects2251 SET2252 deleted_at = ct.now,2253 first_deleted_at = COALESCE(first_deleted_at, ct.now)2254 FROM stale_objects, ct2255 WHERE objects.key = stale_objects.key2256 22572026/11/01 17:56:24 WARN Request failed, retrying attempt=5 backoff=1.512543696s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2258--- PASS: TestGCEndsOnShutdown (0.02s)2259 --- PASS: TestGCEndsOnShutdown/before_the_run (10.31s)2260 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (10.25s)2261 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (10.15s)22622026/11/01 17:56:24 INFO Received uploads request method=POST path=/api/pending_closures22632026/11/01 17:56:24 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22642026/11/01 17:56:24 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo2265--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.01s)2266 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (12.31s)2267 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (11.92s)2268 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (12.60s)2269 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (13.16s)2270 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (13.38s)22712026/11/01 17:56:24 INFO Received uploads request method=POST path=/api/pending_closures22722026/11/01 17:56:24 INFO Aborted multipart uploads count=0 kept=022732026/11/01 17:56:24 WARN Force mode enabled - objects will be deleted immediately without grace period22742026/11/01 17:56:25 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=022752026/11/01 17:56:25 INFO Vacuumed table table=pending_closures22762026/11/01 17:56:25 INFO Vacuumed table table=pending_objects22772026/11/01 17:56:25 INFO Received uploads request method=POST path=/api/pending_closures22782026/11/01 17:56:25 INFO Vacuumed table table=multipart_uploads22792026/11/01 17:56:25 INFO Vacuumed table table=closures22802026/11/01 17:56:25 INFO Vacuumed table table=objects22812026/11/01 17:56:25 INFO Aborted multipart uploads count=0 kept=022822026/11/01 17:56:25 WARN Force mode enabled - objects will be deleted immediately without grace period22832026/11/01 17:56:25 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=022842026/11/01 17:56:25 INFO Vacuumed table table=pending_closures22852026/11/01 17:56:25 INFO Vacuumed table table=pending_objects22862026/11/01 17:56:25 INFO Vacuumed table table=multipart_uploads22872026/11/01 17:56:25 INFO Vacuumed table table=closures22882026/11/01 17:56:25 INFO Vacuumed table table=objects2289--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2290 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (9.60s)2291 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (9.43s)2292--- PASS: TestClientErrorHandling (0.00s)2293 --- PASS: TestClientErrorHandling/InvalidStorePath (9.84s)2294 --- PASS: TestClientErrorHandling/InvalidAuthToken (10.61s)2295 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.68s)2296PASS2297{"timestamp":"2026-11-01T17:56:26.266702Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56503","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}2298{"timestamp":"2026-11-01T17:56:26.266976Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56111","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}2299{"timestamp":"2026-11-01T17:56:26.26705Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56521","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}2300{"timestamp":"2026-11-01T17:56:26.269171Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56397","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}23012026-11-01 17:56:26.401 UTC [37028] LOG: received smart shutdown request23022026-11-01 17:56:26.402 UTC [37028] LOG: background worker "logical replication launcher" (PID 37038) exited with exit code 123032026-11-01 17:56:26.407 UTC [37033] LOG: shutting down23042026-11-01 17:56:26.407 UTC [37033] LOG: checkpoint starting: shutdown immediate23052026-11-01 17:56:28.043 UTC [37033] LOG: checkpoint complete: wrote 12477 buffers (76.2%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.891 s, sync=0.713 s, total=1.636 s; sync files=35724, longest=0.010 s, average=0.001 s; distance=525288 kB, estimate=525288 kB; lsn=0/21887070, redo lsn=0/2188707023062026-11-01 17:56:28.050 UTC [37028] LOG: database system is shut down2307Running OIDC tests...2308=== RUN TestAudienceForIssuer2309=== PAUSE TestAudienceForIssuer2310=== RUN TestGlobMatch2311=== PAUSE TestGlobMatch2312=== RUN TestValidateToken_ValidToken2313=== PAUSE TestValidateToken_ValidToken2314=== RUN TestValidateToken_WrongAudience2315=== PAUSE TestValidateToken_WrongAudience2316=== RUN TestValidateToken_Expired2317=== PAUSE TestValidateToken_Expired2318=== RUN TestValidateToken_BoundClaimsMismatch2319=== PAUSE TestValidateToken_BoundClaimsMismatch2320=== RUN TestValidateToken_BoundSubjectMismatch2321=== PAUSE TestValidateToken_BoundSubjectMismatch2322=== RUN TestValidateToken_MultipleProviders2323=== PAUSE TestValidateToken_MultipleProviders2324=== RUN TestValidateToken_NoMatchingProvider2325=== PAUSE TestValidateToken_NoMatchingProvider2326=== RUN TestValidateToken_KubernetesServiceAccount2327=== PAUSE TestValidateToken_KubernetesServiceAccount2328=== RUN TestNewValidator_KubernetesRequiresCA2329=== PAUSE TestNewValidator_KubernetesRequiresCA2330=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2331=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2332=== RUN TestPins_ReservedForMatchingRule2333=== PAUSE TestPins_ReservedForMatchingRule2334=== RUN TestPins_TopLevelShorthand2335=== PAUSE TestPins_TopLevelShorthand2336=== RUN TestPins_ConfigValidation2337=== PAUSE TestPins_ConfigValidation2338=== RUN TestScopes_LegacyProviderDefaultsToWrite2339=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2340=== RUN TestScopes_Rules2341=== PAUSE TestScopes_Rules2342=== RUN TestScopes_ConfigValidation2343=== PAUSE TestScopes_ConfigValidation2344=== CONT TestAudienceForIssuer2345--- PASS: TestAudienceForIssuer (0.00s)2346=== CONT TestValidateToken_Expired2347=== CONT TestValidateToken_WrongAudience2348=== CONT TestValidateToken_BoundClaimsMismatch2349=== CONT TestValidateToken_MultipleProviders2350=== CONT TestValidateToken_KubernetesServiceAccount2351=== CONT TestPins_ConfigValidation2352=== CONT TestValidateToken_BoundSubjectMismatch2353=== CONT TestScopes_ConfigValidation2354--- PASS: TestPins_ConfigValidation (0.01s)2355=== CONT TestScopes_LegacyProviderDefaultsToWrite2356=== CONT TestValidateToken_ValidToken2357=== CONT TestScopes_Rules2358--- PASS: TestScopes_ConfigValidation (0.00s)2359=== CONT TestPins_ReservedForMatchingRule2360=== CONT TestPins_TopLevelShorthand2361=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2362=== CONT TestNewValidator_KubernetesRequiresCA2363=== CONT TestGlobMatch2364=== RUN TestGlobMatch/foo_foo2365=== PAUSE TestGlobMatch/foo_foo2366=== RUN TestGlobMatch/foo_bar2367=== PAUSE TestGlobMatch/foo_bar2368=== RUN TestGlobMatch/*_2369=== PAUSE TestGlobMatch/*_2370=== RUN TestGlobMatch/*_anything2371=== PAUSE TestGlobMatch/*_anything2372=== RUN TestGlobMatch/foo*_foo2373=== PAUSE TestGlobMatch/foo*_foo2374=== RUN TestGlobMatch/foo*_foobar2375=== PAUSE TestGlobMatch/foo*_foobar2376=== RUN TestGlobMatch/foo*_bar2377=== PAUSE TestGlobMatch/foo*_bar2378=== RUN TestGlobMatch/*bar_bar2379=== PAUSE TestGlobMatch/*bar_bar2380=== RUN TestGlobMatch/*bar_foobar2381=== PAUSE TestGlobMatch/*bar_foobar2382=== RUN TestGlobMatch/*bar_foo2383=== PAUSE TestGlobMatch/*bar_foo2384=== RUN TestGlobMatch/foo*bar_foobar2385=== PAUSE TestGlobMatch/foo*bar_foobar2386=== RUN TestGlobMatch/foo*bar_foo123bar2387=== PAUSE TestGlobMatch/foo*bar_foo123bar2388=== RUN TestGlobMatch/foo*bar_foobarbaz2389=== PAUSE TestGlobMatch/foo*bar_foobarbaz2390=== RUN TestGlobMatch/*/*_foo/bar2391=== PAUSE TestGlobMatch/*/*_foo/bar2392=== RUN TestGlobMatch/*/*_foo2393=== PAUSE TestGlobMatch/*/*_foo2394=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2395=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2396=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02397=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02398=== RUN TestGlobMatch/refs/*/main_refs/heads/main2399=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2400=== RUN TestGlobMatch/fo?_foo2401=== PAUSE TestGlobMatch/fo?_foo2402=== RUN TestGlobMatch/fo?_fo2403=== PAUSE TestGlobMatch/fo?_fo2404=== RUN TestGlobMatch/fo?_fooo2405=== PAUSE TestGlobMatch/fo?_fooo2406=== RUN TestGlobMatch/?oo_foo2407=== PAUSE TestGlobMatch/?oo_foo2408=== RUN TestGlobMatch/?oo_boo2409=== PAUSE TestGlobMatch/?oo_boo2410=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2411=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2412=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2413=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2414=== CONT TestGlobMatch/foo_foo2415=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2416=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2417=== CONT TestGlobMatch/?oo_boo2418=== CONT TestGlobMatch/?oo_foo2419=== CONT TestGlobMatch/fo?_fooo2420=== CONT TestGlobMatch/fo?_fo2421=== CONT TestGlobMatch/fo?_foo2422=== CONT TestGlobMatch/refs/*/main_refs/heads/main2423=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02424=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2425=== CONT TestGlobMatch/*/*_foo2426=== CONT TestGlobMatch/*/*_foo/bar2427=== CONT TestGlobMatch/foo*bar_foobarbaz2428=== CONT TestGlobMatch/foo*bar_foo123bar2429=== CONT TestGlobMatch/foo*bar_foobar2430=== CONT TestGlobMatch/*bar_foo2431=== CONT TestGlobMatch/*bar_foobar2432=== CONT TestGlobMatch/*bar_bar2433=== CONT TestGlobMatch/foo*_bar2434=== CONT TestGlobMatch/foo*_foobar2435=== CONT TestGlobMatch/foo*_foo2436=== CONT TestGlobMatch/*_anything2437=== CONT TestGlobMatch/*_2438=== CONT TestGlobMatch/foo_bar2439--- PASS: TestGlobMatch (0.00s)2440 --- PASS: TestGlobMatch/foo_foo (0.00s)2441 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2442 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2443 --- PASS: TestGlobMatch/?oo_boo (0.00s)2444 --- PASS: TestGlobMatch/?oo_foo (0.00s)2445 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2446 --- PASS: TestGlobMatch/fo?_fo (0.00s)2447 --- PASS: TestGlobMatch/fo?_foo (0.00s)2448 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2449 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2450 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2451 --- PASS: TestGlobMatch/*/*_foo (0.00s)2452 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2453 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2454 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2455 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2456 --- PASS: TestGlobMatch/*bar_foo (0.00s)2457 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2458 --- PASS: TestGlobMatch/*bar_bar (0.00s)2459 --- PASS: TestGlobMatch/foo*_bar (0.00s)2460 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2461 --- PASS: TestGlobMatch/foo*_foo (0.00s)2462 --- PASS: TestGlobMatch/*_anything (0.00s)2463 --- PASS: TestGlobMatch/*_ (0.00s)2464 --- PASS: TestGlobMatch/foo_bar (0.00s)2465=== CONT TestValidateToken_NoMatchingProvider24662026/11/01 17:56:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56542/oidc2467--- PASS: TestValidateToken_ValidToken (0.06s)24682026/11/01 17:56:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56544/oidc24692026/11/01 17:56:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56545/oidc2470--- PASS: TestPins_TopLevelShorthand (0.07s)2471--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.07s)24722026/11/01 17:56:29 http: TLS handshake error from 127.0.0.1:56549: read tcp 127.0.0.1:56548->127.0.0.1:56549: use of closed network connection2473--- PASS: TestNewValidator_KubernetesRequiresCA (0.08s)24742026/11/01 17:56:29 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324752026/11/01 17:56:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56552/oidc2476--- PASS: TestValidateToken_WrongAudience (0.11s)24772026/11/01 17:56:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56555/oidc24782026/11/01 17:56:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56557/oidc2479--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.09s)2480--- PASS: TestValidateToken_BoundClaimsMismatch (0.11s)2481--- PASS: TestPins_ReservedForMatchingRule (0.10s)24822026/11/01 17:56:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56563/oidc24832026/11/01 17:56:29 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:565612484--- PASS: TestValidateToken_KubernetesServiceAccount (0.13s)2485--- PASS: TestScopes_Rules (0.12s)24862026/11/01 17:56:29 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56550/oidc24872026/11/01 17:56:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56567/oidc2488--- PASS: TestValidateToken_NoMatchingProvider (0.11s)2489--- PASS: TestValidateToken_BoundSubjectMismatch (0.13s)24902026/11/01 17:56:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56570/oidc2491--- PASS: TestValidateToken_Expired (0.16s)24922026/11/01 17:56:29 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56569/oidc24932026/11/01 17:56:29 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:56572/oidc2494--- PASS: TestValidateToken_MultipleProviders (0.28s)2495PASS2496Running hook tests...2497=== RUN TestSendPathsEmpty2498=== PAUSE TestSendPathsEmpty2499=== RUN TestQueueEnqueueAndFetch2500=== PAUSE TestQueueEnqueueAndFetch2501=== RUN TestQueueDeduplication2502=== PAUSE TestQueueDeduplication2503=== RUN TestQueueRemove2504=== PAUSE TestQueueRemove2505=== RUN TestQueueFetchBatchLimit2506=== PAUSE TestQueueFetchBatchLimit2507=== RUN TestQueueRetryMovesToBack2508=== PAUSE TestQueueRetryMovesToBack2509=== RUN TestQueueFetchRemoveLifecycle2510=== PAUSE TestQueueFetchRemoveLifecycle2511=== RUN TestQueueConcurrentWriters2512=== PAUSE TestQueueConcurrentWriters2513=== RUN TestQueueRemoveLargeClosure2514=== PAUSE TestQueueRemoveLargeClosure2515=== RUN TestServerClientIntegration2516--- PASS: TestServerClientIntegration (0.00s)2517=== RUN TestServerQueueError25182026/11/01 17:56:30 ERROR Failed to queue paths error="permission denied" count=12519--- PASS: TestServerQueueError (0.00s)2520=== RUN TestGetListenerSocketActivation2521 server_test.go:145: systemd socket activation does not exist on darwin2522--- SKIP: TestGetListenerSocketActivation (0.00s)2523=== RUN TestServerStalledClientDoesNotBlockShutdown2524=== PAUSE TestServerStalledClientDoesNotBlockShutdown2525=== RUN TestServerBacksOffOnAcceptErrors2526=== PAUSE TestServerBacksOffOnAcceptErrors2527=== RUN TestDrainIsolatesPoisonPath2528=== PAUSE TestDrainIsolatesPoisonPath2529=== RUN TestRunNotBlockedByPoisonHead2530=== PAUSE TestRunNotBlockedByPoisonHead2531=== RUN TestDrainGivesUpWhenServerDown2532=== PAUSE TestDrainGivesUpWhenServerDown2533=== RUN TestFailedPathPrunedByLaterClosure2534=== PAUSE TestFailedPathPrunedByLaterClosure2535=== RUN TestWorkerUploadsAndRemoves2536=== PAUSE TestWorkerUploadsAndRemoves2537=== RUN TestWorkerSkipsGCdPaths2538=== PAUSE TestWorkerSkipsGCdPaths2539=== RUN TestWorkerPrunesClosureDeps2540=== PAUSE TestWorkerPrunesClosureDeps2541=== RUN TestDrainTimeout2542=== PAUSE TestDrainTimeout2543=== RUN TestWorkerRemoveFailureIsNotProgress2544=== PAUSE TestWorkerRemoveFailureIsNotProgress2545=== RUN TestWorkerKeepsPathItCannotStat2546=== PAUSE TestWorkerKeepsPathItCannotStat2547=== CONT TestWorkerUploadsAndRemoves2548=== CONT TestSendPathsEmpty2549--- PASS: TestSendPathsEmpty (0.00s)2550=== CONT TestFailedPathPrunedByLaterClosure2551=== CONT TestDrainGivesUpWhenServerDown2552=== CONT TestRunNotBlockedByPoisonHead2553=== CONT TestDrainIsolatesPoisonPath2554=== CONT TestServerBacksOffOnAcceptErrors25552026/11/01 17:56:30 ERROR Accept failed error="too many open files"2556=== CONT TestServerStalledClientDoesNotBlockShutdown2557=== CONT TestQueueRemoveLargeClosure2558=== CONT TestDrainTimeout2559=== CONT TestQueueConcurrentWriters2560=== CONT TestWorkerKeepsPathItCannotStat2561=== CONT TestWorkerRemoveFailureIsNotProgress2562=== CONT TestQueueFetchRemoveLifecycle2563=== CONT TestWorkerPrunesClosureDeps2564=== CONT TestQueueRetryMovesToBack2565=== CONT TestWorkerSkipsGCdPaths2566=== CONT TestQueueFetchBatchLimit2567=== CONT TestQueueDeduplication2568=== CONT TestQueueEnqueueAndFetch2569=== CONT TestQueueRemove25702026/11/01 17:56:30 ERROR Accept failed error="too many open files"25712026/11/01 17:56:30 INFO Uploading batch count=225722026/11/01 17:56:30 INFO Upload queue status pending=225732026/11/01 17:56:30 INFO Uploading batch count=225742026/11/01 17:56:30 INFO Uploading batch count=125752026/11/01 17:56:30 ERROR Upload failed error="upload failed" count=125762026/11/01 17:56:30 INFO Upload queue status pending=225772026/11/01 17:56:30 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestWorkerSkipsGCdPaths178460038/002/nonexistent25782026/11/01 17:56:30 INFO Uploading batch count=225792026/11/01 17:56:30 ERROR Upload failed error="upload failed" count=225802026/11/01 17:56:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestDrainGivesUpWhenServerDown3136941236/002/a25812026/11/01 17:56:30 INFO Uploading batch count=125822026/11/01 17:56:30 INFO Uploading batch count=125832026/11/01 17:56:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestDrainGivesUpWhenServerDown3136941236/002/b25842026/11/01 17:56:30 INFO Upload queue status pending=325852026/11/01 17:56:30 INFO Upload queue status pending=225862026/11/01 17:56:30 WARN Cannot stat store path, will retry later path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestWorkerKeepsPathItCannotStat3872595265/002/locked/aaa error="stat /private/var/tb/8/scratch/90a332d44a448eb6/build/TestWorkerKeepsPathItCannotStat3872595265/002/locked/aaa: permission denied"25872026/11/01 17:56:30 WARN Cannot stat store path, will retry later path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestWorkerKeepsPathItCannotStat3872595265/002/locked/aaa error="stat /private/var/tb/8/scratch/90a332d44a448eb6/build/TestWorkerKeepsPathItCannotStat3872595265/002/locked/aaa: permission denied"2588--- PASS: TestQueueFetchBatchLimit (0.01s)25892026/11/01 17:56:30 INFO Uploading batch count=12590--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25912026/11/01 17:56:30 WARN Cannot stat store path, will retry later path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestWorkerKeepsPathItCannotStat3872595265/002/locked/aaa error="stat /private/var/tb/8/scratch/90a332d44a448eb6/build/TestWorkerKeepsPathItCannotStat3872595265/002/locked/aaa: permission denied"25922026/11/01 17:56:30 INFO Uploading batch count=225932026/11/01 17:56:30 ERROR Upload failed error="upload failed" count=225942026/11/01 17:56:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestDrainGivesUpWhenServerDown3136941236/002/c25952026/11/01 17:56:30 INFO Uploading batch count=125962026/11/01 17:56:30 ERROR Upload failed error="upload failed" count=125972026/11/01 17:56:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestDrainGivesUpWhenServerDown3136941236/002/d25982026/11/01 17:56:30 ERROR Drain finished with paths left in queue remaining=125992026/11/01 17:56:30 INFO Uploading batch count=126002026/11/01 17:56:30 INFO Uploading batch count=426012026/11/01 17:56:30 ERROR Upload failed error="upload failed" count=426022026/11/01 17:56:30 INFO Uploading batch count=226032026/11/01 17:56:30 ERROR Upload failed error="upload failed" count=226042026/11/01 17:56:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestDrainGivesUpWhenServerDown3136941236/002/e2605--- PASS: TestQueueDeduplication (0.01s)26062026/11/01 17:56:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestDrainGivesUpWhenServerDown3136941236/002/f26072026/11/01 17:56:30 ERROR Drain finished with paths left in queue remaining=102608--- PASS: TestQueueRemove (0.01s)26092026/11/01 17:56:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestDrainIsolatesPoisonPath3069541531/002/bbb2610--- PASS: TestWorkerKeepsPathItCannotStat (0.01s)26112026/11/01 17:56:30 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestWorkerRemoveFailureIsNotProgress4217127610/002/nonexistent26122026/11/01 17:56:30 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126132026/11/01 17:56:30 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestWorkerRemoveFailureIsNotProgress4217127610/002/nonexistent26142026/11/01 17:56:30 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126152026/11/01 17:56:30 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/8/scratch/90a332d44a448eb6/build/TestWorkerRemoveFailureIsNotProgress4217127610/002/nonexistent26162026/11/01 17:56:30 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126172026/11/01 17:56:30 ERROR Drain finished with paths left in queue remaining=126182026/11/01 17:56:30 INFO Uploading batch count=126192026/11/01 17:56:30 ERROR Upload failed error="upload failed" count=12620--- PASS: TestQueueEnqueueAndFetch (0.01s)26212026/11/01 17:56:30 ERROR Accept failed error="too many open files"2622--- PASS: TestWorkerRemoveFailureIsNotProgress (0.01s)26232026/11/01 17:56:30 INFO Uploading batch count=126242026/11/01 17:56:30 ERROR Upload failed error="upload failed" count=126252026/11/01 17:56:30 INFO Uploading batch count=126262026/11/01 17:56:30 ERROR Upload failed error="upload failed" count=12627--- PASS: TestQueueRetryMovesToBack (0.01s)2628--- PASS: TestDrainGivesUpWhenServerDown (0.02s)26292026/11/01 17:56:30 ERROR Drain finished with paths left in queue remaining=12630--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2631--- PASS: TestDrainIsolatesPoisonPath (0.02s)2632--- PASS: TestWorkerUploadsAndRemoves (0.03s)2633--- PASS: TestWorkerSkipsGCdPaths (0.03s)2634--- PASS: TestWorkerPrunesClosureDeps (0.03s)26352026/11/01 17:56:30 ERROR Accept failed error="too many open files"2636--- PASS: TestQueueRemoveLargeClosure (0.04s)2637--- PASS: TestQueueConcurrentWriters (0.04s)26382026/11/01 17:56:30 ERROR Accept failed error="too many open files"26392026/11/01 17:56:30 ERROR Accept failed error="too many open files"26402026/11/01 17:56:30 ERROR Failed to decode request error="read unix /private/var/tb/8/scratch/90a332d44a448eb6/build/hook2891744893/test.sock->: i/o timeout"26412026/11/01 17:56:30 ERROR Failed to write response error="write unix /private/var/tb/8/scratch/90a332d44a448eb6/build/hook2891744893/test.sock->: i/o timeout"2642--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26432026/11/01 17:56:30 ERROR Upload failed error="context deadline exceeded" count=226442026/11/01 17:56:30 ERROR Drain finished with paths left in queue remaining=42645--- PASS: TestDrainTimeout (0.21s)26462026/11/01 17:56:30 ERROR Accept failed error="too many open files"26472026/11/01 17:56:30 ERROR Accept failed error="too many open files"2648--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26492026/11/01 17:56:31 INFO Uploading batch count=126502026/11/01 17:56:31 INFO Uploading batch count=126512026/11/01 17:56:31 INFO Uploading batch count=126522026/11/01 17:56:31 ERROR Upload failed error="upload failed" count=126532026/11/01 17:56:31 INFO Uploading batch count=126542026/11/01 17:56:31 ERROR Upload failed error="upload failed" count=126552026/11/01 17:56:31 INFO Uploading batch count=126562026/11/01 17:56:31 ERROR Upload failed error="upload failed" count=126572026/11/01 17:56:31 INFO Uploading batch count=126582026/11/01 17:56:31 ERROR Upload failed error="upload failed" count=126592026/11/01 17:56:31 ERROR Drain finished with paths left in queue remaining=12660--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2661PASS2662Running signing tests...2663=== RUN TestExternalSigner2664=== PAUSE TestExternalSigner2665=== RUN TestExternalSignerWrongPublicKey2666=== PAUSE TestExternalSignerWrongPublicKey2667=== RUN TestExternalSignerErrors2668=== PAUSE TestExternalSignerErrors2669=== RUN TestExternalSignerRestartsAfterCrash2670=== PAUSE TestExternalSignerRestartsAfterCrash2671=== RUN TestExternalSignerProgramErrorKeepsProcess2672=== PAUSE TestExternalSignerProgramErrorKeepsProcess2673=== RUN TestExternalSignerClose2674=== PAUSE TestExternalSignerClose2675=== RUN TestExternalSignerRejectsInvalidPublicKey2676=== PAUSE TestExternalSignerRejectsInvalidPublicKey2677=== RUN TestExternalSignerCancellation2678=== PAUSE TestExternalSignerCancellation2679=== RUN TestGenerateFingerprint2680=== PAUSE TestGenerateFingerprint2681=== RUN TestParseSigningKey2682=== PAUSE TestParseSigningKey2683=== RUN TestSign2684=== PAUSE TestSign2685=== RUN TestSignBatch2686=== PAUSE TestSignBatch2687=== RUN TestNilKeyPublicKey2688=== PAUSE TestNilKeyPublicKey2689=== RUN TestSignErrors2690=== PAUSE TestSignErrors2691=== CONT TestExternalSigner2692=== CONT TestExternalSignerCancellation2693=== CONT TestSignBatch2694=== CONT TestExternalSignerProgramErrorKeepsProcess2695=== CONT TestSignErrors2696=== CONT TestExternalSignerErrors2697=== RUN TestExternalSignerErrors/exit_on_request2698=== PAUSE TestExternalSignerErrors/exit_on_request2699=== RUN TestExternalSignerErrors/wrong_shape2700=== PAUSE TestExternalSignerErrors/wrong_shape2701=== RUN TestExternalSignerErrors/wrong_id2702=== PAUSE TestExternalSignerErrors/wrong_id2703=== RUN TestExternalSignerErrors/null_signatures2704=== PAUSE TestExternalSignerErrors/null_signatures2705=== RUN TestExternalSignerErrors/missing_signature_name2706=== PAUSE TestExternalSignerErrors/missing_signature_name2707=== RUN TestExternalSignerErrors/invalid_signature_base642708=== PAUSE TestExternalSignerErrors/invalid_signature_base642709=== RUN TestExternalSignerErrors/program_error2710=== PAUSE TestExternalSignerErrors/program_error2711=== RUN TestExternalSignerErrors/invalid_JSON2712=== PAUSE TestExternalSignerErrors/invalid_JSON2713=== RUN TestExternalSignerErrors/null2714=== PAUSE TestExternalSignerErrors/null2715=== RUN TestExternalSignerErrors/wrong_signature_name2716=== PAUSE TestExternalSignerErrors/wrong_signature_name2717=== RUN TestExternalSignerErrors/wrong_signature_length2718=== PAUSE TestExternalSignerErrors/wrong_signature_length2719=== RUN TestExternalSignerErrors/missing_signatures2720=== PAUSE TestExternalSignerErrors/missing_signatures2721=== RUN TestExternalSignerErrors/too_few_signatures2722=== PAUSE TestExternalSignerErrors/too_few_signatures2723=== RUN TestExternalSignerErrors/exit_at_startup2724=== PAUSE TestExternalSignerErrors/exit_at_startup2725=== RUN TestExternalSignerErrors/wrong_signatures_shape2726=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2727=== RUN TestExternalSignerErrors/unrequested_key2728=== PAUSE TestExternalSignerErrors/unrequested_key2729=== CONT TestExternalSignerErrors/exit_on_request2730=== CONT TestExternalSignerRejectsInvalidPublicKey2731=== CONT TestExternalSignerWrongPublicKey2732=== RUN TestExternalSignerRejectsInvalidPublicKey/#002733=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002734=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2735=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2736=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2737=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2738=== CONT TestExternalSignerRestartsAfterCrash2739=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2740=== CONT TestNilKeyPublicKey2741=== CONT TestExternalSignerClose2742=== CONT TestExternalSignerErrors/null2743=== CONT TestExternalSignerErrors/null_signatures2744=== CONT TestExternalSignerErrors/too_few_signatures2745=== CONT TestExternalSignerErrors/missing_signature_name2746=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2747=== CONT TestExternalSignerErrors/wrong_signature_length2748=== CONT TestSign2749=== CONT TestExternalSignerErrors/invalid_JSON2750=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2751=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2752=== CONT TestGenerateFingerprint2753=== RUN TestGenerateFingerprint/basic_with_references2754--- PASS: TestNilKeyPublicKey (0.00s)2755=== CONT TestExternalSignerErrors/wrong_signatures_shape2756=== CONT TestExternalSignerErrors/program_error2757=== CONT TestExternalSignerErrors/invalid_signature_base642758=== CONT TestExternalSignerErrors/wrong_id2759=== CONT TestExternalSignerErrors/wrong_shape2760=== CONT TestExternalSignerErrors/missing_signatures2761=== CONT TestExternalSignerErrors/wrong_signature_name2762--- PASS: TestSign (0.00s)2763=== CONT TestExternalSignerErrors/unrequested_key2764--- PASS: TestSignBatch (0.00s)2765=== CONT TestExternalSignerErrors/exit_at_startup2766=== PAUSE TestGenerateFingerprint/basic_with_references2767=== RUN TestGenerateFingerprint/no_references2768=== PAUSE TestGenerateFingerprint/no_references2769=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2770=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2771=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2772=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2773=== RUN TestGenerateFingerprint/invalid_nar_hash_length2774=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2775=== RUN TestGenerateFingerprint/invalid_store_path_prefix2776=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2777=== RUN TestGenerateFingerprint/invalid_reference_prefix2778=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2779=== RUN TestSignErrors/nil_key2780=== PAUSE TestSignErrors/nil_key2781=== RUN TestSignErrors/nil_narinfo2782=== PAUSE TestSignErrors/nil_narinfo2783=== RUN TestSignErrors/invalid_narinfo2784=== PAUSE TestSignErrors/invalid_narinfo2785=== RUN TestSignErrors/canceled2786=== PAUSE TestSignErrors/canceled2787=== CONT TestParseSigningKey2788=== RUN TestParseSigningKey/valid_32-byte_key2789=== PAUSE TestParseSigningKey/valid_32-byte_key2790=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2791=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2792=== RUN TestParseSigningKey/no_colon2793=== PAUSE TestParseSigningKey/no_colon2794=== RUN TestParseSigningKey/empty_name2795=== PAUSE TestParseSigningKey/empty_name2796=== RUN TestParseSigningKey/invalid_base642797=== PAUSE TestParseSigningKey/invalid_base642798=== RUN TestParseSigningKey/wrong_length2799=== PAUSE TestParseSigningKey/wrong_length2800=== CONT TestExternalSignerRejectsInvalidPublicKey/#002801=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2802=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2803=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2804=== CONT TestGenerateFingerprint/basic_with_references2805=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2806=== CONT TestSignErrors/nil_key2807=== CONT TestParseSigningKey/valid_32-byte_key2808=== CONT TestGenerateFingerprint/invalid_store_path_prefix2809=== CONT TestGenerateFingerprint/invalid_nar_hash_length2810--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2811 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2812 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2813 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2814 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2815 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2816=== CONT TestGenerateFingerprint/invalid_reference_prefix2817=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2818=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2819=== CONT TestGenerateFingerprint/no_references2820=== CONT TestParseSigningKey/wrong_length2821=== CONT TestSignErrors/canceled2822=== CONT TestSignErrors/invalid_narinfo2823=== CONT TestSignErrors/nil_narinfo2824=== CONT TestParseSigningKey/empty_name2825=== CONT TestParseSigningKey/no_colon2826=== CONT TestParseSigningKey/invalid_base642827--- PASS: TestGenerateFingerprint (0.00s)2828 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2829 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2830 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2831 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2832 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2833 --- PASS: TestGenerateFingerprint/no_references (0.00s)2834 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2835=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2836--- PASS: TestSignErrors (0.00s)2837 --- PASS: TestSignErrors/nil_key (0.00s)2838 --- PASS: TestSignErrors/canceled (0.00s)2839 --- PASS: TestSignErrors/nil_narinfo (0.00s)2840 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2841--- PASS: TestParseSigningKey (0.00s)2842 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2843 --- PASS: TestParseSigningKey/wrong_length (0.00s)2844 --- PASS: TestParseSigningKey/empty_name (0.00s)2845 --- PASS: TestParseSigningKey/no_colon (0.00s)2846 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2847 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2848--- PASS: TestExternalSignerCancellation (0.11s)2849--- PASS: TestExternalSigner (0.34s)2850--- PASS: TestExternalSignerRestartsAfterCrash (0.82s)2851/private/var/tb/8/scratch/90a332d44a448eb6/build/TestExternalSignerRestartsAfterCrash2636595845/001/sign program: line 7: /private/var/tb/8/scratch/90a332d44a448eb6/build/TestExternalSignerRestartsAfterCrash2636595845/001/sign program.starts: No such file or directory2852--- PASS: TestExternalSignerClose (0.88s)2853--- PASS: TestExternalSignerProgramErrorKeepsProcess (1.04s)2854--- PASS: TestExternalSignerWrongPublicKey (1.20s)2855--- PASS: TestExternalSignerErrors (0.00s)2856 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.17s)2857 --- PASS: TestExternalSignerErrors/null (0.25s)2858 --- PASS: TestExternalSignerErrors/wrong_shape (0.41s)2859 --- PASS: TestExternalSignerErrors/unrequested_key (0.48s)2860 --- PASS: TestExternalSignerErrors/too_few_signatures (0.56s)2861 --- PASS: TestExternalSignerErrors/null_signatures (0.64s)2862 --- PASS: TestExternalSignerErrors/exit_on_request (0.72s)2863 --- PASS: TestExternalSignerErrors/exit_at_startup (0.96s)2864 --- PASS: TestExternalSignerErrors/missing_signature_name (1.12s)2865 --- PASS: TestExternalSignerErrors/missing_signatures (1.27s)2866 --- PASS: TestExternalSignerErrors/program_error (1.35s)2867 --- PASS: TestExternalSignerErrors/invalid_JSON (1.43s)2868 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.51s)2869 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.59s)2870 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.67s)2871 --- PASS: TestExternalSignerErrors/wrong_id (1.75s)2872PASS2873Running OpenBao signer tests...2874=== RUN TestSign2875=== PAUSE TestSign2876=== RUN TestSignErrors2877=== PAUSE TestSignErrors2878=== RUN TestServe2879=== PAUSE TestServe2880=== RUN TestServeRejectsGarbage2881=== PAUSE TestServeRejectsGarbage2882=== CONT TestSign2883=== CONT TestServeRejectsGarbage2884=== CONT TestSignErrors2885=== CONT TestServe2886--- PASS: TestServeRejectsGarbage (0.00s)2887=== RUN TestSignErrors/http_error2888=== PAUSE TestSignErrors/http_error2889=== RUN TestSignErrors/invalid_json2890=== PAUSE TestSignErrors/invalid_json2891=== RUN TestSignErrors/no_prefix2892=== PAUSE TestSignErrors/no_prefix2893=== RUN TestSignErrors/invalid_base642894=== PAUSE TestSignErrors/invalid_base642895=== CONT TestSignErrors/http_error2896=== CONT TestSignErrors/no_prefix2897--- PASS: TestServe (0.00s)2898=== CONT TestSignErrors/invalid_base642899=== CONT TestSignErrors/invalid_json2900--- PASS: TestSign (0.00s)2901--- PASS: TestSignErrors (0.00s)2902 --- PASS: TestSignErrors/invalid_base64 (0.00s)2903 --- PASS: TestSignErrors/http_error (0.00s)2904 --- PASS: TestSignErrors/invalid_json (0.00s)2905 --- PASS: TestSignErrors/no_prefix (0.00s)2906PASS