niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #406
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica8=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica9=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun10=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun11=== RUN TestCaseHackSuffix12=== PAUSE TestCaseHackSuffix13=== RUN TestFilterOversizedClosures14=== PAUSE TestFilterOversizedClosures15=== RUN TestUploadMultipart_PartsInParallel16=== PAUSE TestUploadMultipart_PartsInParallel17=== RUN TestPartSizeForNAR18=== PAUSE TestPartSizeForNAR19=== RUN TestUploadMultipart_SupersededByPeer20=== PAUSE TestUploadMultipart_SupersededByPeer21=== RUN TestDumpPathCaseHackMatchesNix22--- PASS: TestDumpPathCaseHackMatchesNix (0.06s)23=== RUN TestDumpPathCaseHackCollision24--- PASS: TestDumpPathCaseHackCollision (0.00s)25=== RUN TestDumpPathMatchesNix26=== PAUSE TestDumpPathMatchesNix27=== RUN TestDumpPathSingleFile28=== PAUSE TestDumpPathSingleFile29=== RUN TestDumpPathWriterError30=== PAUSE TestDumpPathWriterError31=== RUN TestEncodeNixBase3232=== PAUSE TestEncodeNixBase3233=== RUN TestEncodeNixBase32WithRealHash34=== PAUSE TestEncodeNixBase32WithRealHash35=== RUN TestConvertHashToNix3236=== PAUSE TestConvertHashToNix3237=== RUN TestGetStorePathHash38=== PAUSE TestGetStorePathHash39=== RUN TestPathInfoHashCompatibility40=== PAUSE TestPathInfoHashCompatibility41=== RUN TestParsePathInfoJSON42=== PAUSE TestParsePathInfoJSON43=== RUN TestParsePathInfoJSONMultiplePaths44=== PAUSE TestParsePathInfoJSONMultiplePaths45=== RUN TestPathInfoCACompatibility46=== PAUSE TestPathInfoCACompatibility47=== RUN TestRateLimiterFeedback48=== PAUSE TestRateLimiterFeedback49=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess50=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess51=== RUN TestResolveStorePath52=== PAUSE TestResolveStorePath53=== RUN TestDoWithRetry_BodyReplayedViaGetBody54=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody55=== RUN TestRetryTimeoutOutlastsMaxRetries56=== PAUSE TestRetryTimeoutOutlastsMaxRetries57=== RUN TestShellSplit58=== PAUSE TestShellSplit59=== RUN TestShellSplitErrors60=== PAUSE TestShellSplitErrors61=== RUN TestStreamPushReportsEveryPath62=== PAUSE TestStreamPushReportsEveryPath63=== RUN TestStreamPushBatchesUnderLoad64=== PAUSE TestStreamPushBatchesUnderLoad65=== RUN TestStreamPushIsolatesFailures66=== PAUSE TestStreamPushIsolatesFailures67=== RUN TestStreamPushGivesUpOnDeadServer68=== PAUSE TestStreamPushGivesUpOnDeadServer69=== RUN TestStreamPushRequestLine70=== PAUSE TestStreamPushRequestLine71=== RUN TestStreamPushReportsSignatures72=== PAUSE TestStreamPushReportsSignatures73=== RUN TestStreamPushReportsSkippedPaths74=== PAUSE TestStreamPushReportsSkippedPaths75=== RUN TestClientSignaturesByStorePath76=== PAUSE TestClientSignaturesByStorePath77=== RUN TestStreamPushStopsWhenCanceled78=== PAUSE TestStreamPushStopsWhenCanceled79=== RUN TestSetClientTLS80=== PAUSE TestSetClientTLS81=== RUN TestSetClientTLSDoesNotMutateDefaultTransport82=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport83=== RUN TestSetClientTLSErrors84=== PAUSE TestSetClientTLSErrors85=== RUN TestStaticToken86=== PAUSE TestStaticToken87=== RUN TestFileTokenReadsAndCaches88=== PAUSE TestFileTokenReadsAndCaches89=== RUN TestFileTokenMissing90=== PAUSE TestFileTokenMissing91=== RUN TestFileTokenEmpty92=== PAUSE TestFileTokenEmpty93=== RUN TestScriptTokenNoExpiryRerunsEveryCall94=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall95=== RUN TestScriptTokenCachesUntilRefresh96=== PAUSE TestScriptTokenCachesUntilRefresh97=== RUN TestScriptTokenEmptyToken98=== PAUSE TestScriptTokenEmptyToken99=== RUN TestScriptTokenBadJSON100=== PAUSE TestScriptTokenBadJSON101=== RUN TestScriptTokenScriptFails102=== PAUSE TestScriptTokenScriptFails103=== RUN TestScriptTokenEmptyCommand104=== PAUSE TestScriptTokenEmptyCommand105=== CONT TestDoServerRequestAttachesToken106=== CONT TestStreamPushReportsSignatures107=== CONT TestPathInfoHashCompatibility108=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)109=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)110=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon111=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon112=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI113=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI114=== CONT TestStreamPushRequestLine115=== CONT TestStreamPushGivesUpOnDeadServer116=== CONT TestStreamPushIsolatesFailures117=== CONT TestStreamPushBatchesUnderLoad118=== CONT TestStreamPushReportsEveryPath119=== CONT TestShellSplitErrors120--- PASS: TestShellSplitErrors (0.00s)121=== CONT TestRateLimiterFeedback122=== RUN TestRateLimiterFeedback/429_enables_limiter123=== PAUSE TestRateLimiterFeedback/429_enables_limiter124=== RUN TestRateLimiterFeedback/503_enables_limiter125=== PAUSE TestRateLimiterFeedback/503_enables_limiter126=== CONT TestShellSplit127=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter128=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter129=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter130=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter131--- PASS: TestShellSplit (0.00s)132=== CONT TestDoWithRetry_BodyReplayedViaGetBody1332026/10/10 19:01:46 ERROR Upload failed error="connection refused" count=201342026/10/10 19:01:46 ERROR Upload failed error="bad path" count=3135=== CONT TestResolveStorePath1362026/10/10 19:01:46 ERROR Server seems unavailable, giving up on batch untried=17137=== CONT TestPathInfoCACompatibility138=== RUN TestPathInfoCACompatibility/null_ca_field139=== CONT TestParsePathInfoJSONMultiplePaths140=== CONT TestParsePathInfoJSON141=== CONT TestUploadMultipart_SupersededByPeer142=== CONT TestGetStorePathHash143=== CONT TestConvertHashToNix32144=== CONT TestEncodeNixBase32WithRealHash145=== CONT TestEncodeNixBase32146=== CONT TestDumpPathWriterError147=== CONT TestDumpPathSingleFile148=== CONT TestDumpPathMatchesNix149=== CONT TestFileTokenMissing150=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512151=== RUN TestUploadMultipart_SupersededByPeer/exists152=== PAUSE TestUploadMultipart_SupersededByPeer/exists153=== RUN TestUploadMultipart_SupersededByPeer/missing154=== PAUSE TestUploadMultipart_SupersededByPeer/missing155=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512156=== CONT TestScriptTokenScriptFails157=== RUN TestGetStorePathHash/valid_store_path158=== PAUSE TestGetStorePathHash/valid_store_path159=== RUN TestGetStorePathHash/basename_without_hyphen_should_error160=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error161=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error162=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1632026/10/10 19:01:46 ERROR Upload failed error=boom count=1164=== RUN TestEncodeNixBase32/test_string_hash165=== CONT TestScriptTokenEmptyToken166=== CONT TestSetClientTLSDoesNotMutateDefaultTransport1672026/10/10 19:01:46 WARN Rate limiter enabled after throttle name=server-test rate=5168=== PAUSE TestEncodeNixBase32/test_string_hash169=== CONT TestScriptTokenEmptyCommand170=== CONT TestScriptTokenCachesUntilRefresh171=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths172=== CONT TestRetryTimeoutOutlastsMaxRetries173=== RUN TestConvertHashToNix32/SRI_format_to_Nix32174=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error175--- PASS: TestEncodeNixBase32WithRealHash (0.00s)176--- PASS: TestStreamPushReportsSignatures (0.00s)177=== CONT TestScriptTokenBadJSON178=== CONT TestFileTokenReadsAndCaches179=== RUN TestParsePathInfoJSON/Nix_format180=== PAUSE TestParsePathInfoJSON/Nix_format181=== RUN TestParsePathInfoJSON/Lix_format182=== PAUSE TestParsePathInfoJSON/Lix_format183=== RUN TestParsePathInfoJSON/empty_input184=== PAUSE TestParsePathInfoJSON/empty_input185=== RUN TestParsePathInfoJSON/whitespace_only1862026/10/10 19:01:46 ERROR Upload failed error=boom count=1187=== PAUSE TestParsePathInfoJSON/whitespace_only188=== RUN TestParsePathInfoJSON/invalid_JSON189=== CONT TestScriptTokenNoExpiryRerunsEveryCall190=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths191--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)192--- PASS: TestScriptTokenEmptyCommand (0.00s)193=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error194=== RUN TestEncodeNixBase32/empty_input195=== PAUSE TestPathInfoCACompatibility/null_ca_field196=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32197=== CONT TestStaticToken198=== CONT TestFileTokenEmpty199--- PASS: TestStreamPushReportsEveryPath (0.00s)200--- PASS: TestStreamPushIsolatesFailures (0.00s)201--- PASS: TestResolveStorePath (0.00s)202=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths203--- PASS: TestStaticToken (0.00s)204=== CONT TestSetClientTLSErrors205--- PASS: TestFileTokenReadsAndCaches (0.00s)206--- PASS: TestScriptTokenScriptFails (0.00s)207=== CONT TestSetClientTLS208--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)209=== CONT TestClientSignaturesByStorePath210--- PASS: TestClientSignaturesByStorePath (0.00s)211=== PAUSE TestParsePathInfoJSON/invalid_JSON212=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica213=== CONT TestCaseHackSuffix2142026/10/10 19:01:46 WARN Rate limiter enabled after throttle name=server-test rate=52152026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:63543216=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths217=== CONT TestUploadMultipart_PartsInParallel218=== RUN TestConvertHashToNix32/already_Nix32_format219=== CONT TestStreamPushStopsWhenCanceled220=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error221--- PASS: TestFileTokenMissing (0.00s)222--- PASS: TestDoServerRequestAttachesToken (0.01s)223=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun224=== RUN TestSetClientTLSErrors/missing_cert_file225=== PAUSE TestConvertHashToNix32/already_Nix32_format226=== RUN TestConvertHashToNix32/invalid_format2272026/10/10 19:01:46 WARN Rate limiter backed off name=server-test rate=52282026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:635432292026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:63548230=== CONT TestPartSizeForNAR231=== RUN TestPartSizeForNAR/zero_stays_at_minimum232=== PAUSE TestEncodeNixBase32/empty_input233=== PAUSE TestSetClientTLSErrors/missing_cert_file234=== RUN TestPathInfoCACompatibility/old_string_format_-_text2352026/10/10 19:01:46 INFO Garbage collection started236=== CONT TestRegisterUploadedObjectReusesConnections237=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum238=== RUN TestPartSizeForNAR/small_stays_at_minimum239=== PAUSE TestPartSizeForNAR/small_stays_at_minimum240=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum241=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum242=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts243=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts244=== RUN TestPartSizeForNAR/1_TiB245=== PAUSE TestPartSizeForNAR/1_TiB246=== RUN TestPartSizeForNAR/5_TiB_S3_max_object247=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object248=== RUN TestPartSizeForNAR/capped_at_5_GiB249=== PAUSE TestPartSizeForNAR/capped_at_5_GiB250=== CONT TestStreamPushReportsSkippedPaths251=== CONT TestRateLimiterFeedback/429_enables_limiter252=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter253--- PASS: TestStreamPushStopsWhenCanceled (0.00s)254--- PASS: TestStreamPushReportsSkippedPaths (0.00s)255=== CONT TestFilterOversizedClosures256=== PAUSE TestConvertHashToNix32/invalid_format257=== CONT TestRateLimiterFeedback/503_enables_limiter258--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)259--- PASS: TestFileTokenEmpty (0.01s)260=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter261=== RUN TestFilterOversizedClosures/no_limit_keeps_everything262=== RUN TestSetClientTLSErrors/missing_key_file263=== PAUSE TestSetClientTLSErrors/missing_key_file264=== RUN TestSetClientTLSErrors/missing_ca_file265--- PASS: TestScriptTokenBadJSON (0.01s)266=== CONT TestUploadMultipart_SupersededByPeer/exists267--- PASS: TestScriptTokenEmptyToken (0.01s)268=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)269=== CONT TestUploadMultipart_SupersededByPeer/missing2702026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:63548271=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text272=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive273=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive274=== RUN TestPathInfoCACompatibility/new_structured_format_-_text275=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text276=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method277=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method278=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512279=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI280=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon281--- PASS: TestPathInfoHashCompatibility (0.00s)282 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)283 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)284 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)285 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)286=== CONT TestParsePathInfoJSON/invalid_JSON287=== CONT TestParsePathInfoJSON/Nix_format288=== PAUSE TestSetClientTLSErrors/missing_ca_file289=== RUN TestSetClientTLSErrors/invalid_ca_file290=== PAUSE TestSetClientTLSErrors/invalid_ca_file291--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)2922026/10/10 19:01:46 WARN Rate limiter enabled after throttle name=server-test rate=5293=== CONT TestParsePathInfoJSON/Lix_format2942026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:63556295=== CONT TestParsePathInfoJSON/empty_input296=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths297=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths298=== CONT TestGetStorePathHash/valid_store_path299=== CONT TestParsePathInfoJSON/whitespace_only300=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error301=== CONT TestGetStorePathHash/basename_without_hyphen_should_error302=== CONT TestEncodeNixBase32/empty_input303=== RUN TestSetClientTLS/rejects_connection_without_client_cert304=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert305=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA306=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA307=== RUN TestSetClientTLS/preserves_debug_logging_transport308=== PAUSE TestSetClientTLS/preserves_debug_logging_transport309=== CONT TestPartSizeForNAR/capped_at_5_GiB310=== CONT TestPartSizeForNAR/zero_stays_at_minimum311=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts312=== CONT TestPartSizeForNAR/5_TiB_S3_max_object313=== CONT TestConvertHashToNix32/SRI_format_to_Nix32314=== CONT TestPartSizeForNAR/small_stays_at_minimum315=== CONT TestConvertHashToNix32/invalid_format316=== CONT TestConvertHashToNix32/already_Nix32_format317=== CONT TestPathInfoCACompatibility/null_ca_field318=== CONT TestPathInfoCACompatibility/new_structured_format_-_text319=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method3202026/10/10 19:01:46 WARN Rate limiter backed off name=server-test rate=5321=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive322=== CONT TestSetClientTLSErrors/missing_cert_file323=== CONT TestSetClientTLSErrors/missing_ca_file324--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)325 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)326 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)327--- PASS: TestParsePathInfoJSON (0.00s)328 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)329 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)330 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)331 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)332 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)333=== CONT TestEncodeNixBase32/test_string_hash334--- PASS: TestEncodeNixBase32 (0.01s)335 --- PASS: TestEncodeNixBase32/empty_input (0.00s)336 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)337=== CONT TestPartSizeForNAR/1_TiB338=== CONT TestSetClientTLS/rejects_connection_without_client_cert339=== CONT TestSetClientTLS/preserves_debug_logging_transport340=== CONT TestSetClientTLSErrors/missing_key_file341=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA342=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum343=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error344--- PASS: TestGetStorePathHash (0.01s)345 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)346 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)347 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)348 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)349=== CONT TestPathInfoCACompatibility/old_string_format_-_text350=== CONT TestSetClientTLSErrors/invalid_ca_file351--- PASS: TestPartSizeForNAR (0.00s)352 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)353 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)354 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)355 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)356 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)357 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)358 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)359--- PASS: TestConvertHashToNix32 (0.01s)360 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)361 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)362 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)363--- PASS: TestPathInfoCACompatibility (0.01s)364 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)365 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)366 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)367 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)368 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)369=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything370--- PASS: TestSetClientTLSErrors (0.01s)371 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)372 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)373 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)374 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)375=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped376=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped377=== RUN TestFilterOversizedClosures/all_closures_skipped378=== PAUSE TestFilterOversizedClosures/all_closures_skipped379=== CONT TestFilterOversizedClosures/no_limit_keeps_everything380=== CONT TestFilterOversizedClosures/all_closures_skipped3812026/10/10 19:01:46 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=50382=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3832026/10/10 19:01:46 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=2000384--- PASS: TestFilterOversizedClosures (0.01s)385 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)386 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)387 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)3882026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:635483892026/10/10 19:01:46 INFO Garbage collection started3902026/10/10 19:01:46 WARN Rate limiter enabled after throttle name=server-test rate=53912026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:635613922026/10/10 19:01:46 WARN Rate limiter backed off name=server-test rate=5393--- PASS: TestRateLimiterFeedback (0.00s)394 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)395 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)396 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)397 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)3982026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:635483992026/10/10 19:01:46 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=0400--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)401 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)402 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)4032026/10/10 19:01:46 WARN Garbage collection finished on another replica. Its statistics are not available here404--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)4052026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:63548406--- PASS: TestStreamPushRequestLine (0.02s)4072026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:635484082026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:635484092026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:635484102026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:635484112026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:635484122026/10/10 19:01:46 http: TLS handshake error from 127.0.0.1:63572: remote error: tls: bad certificate413--- PASS: TestSetClientTLS (0.01s)414 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)415 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)416 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4172026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:635484182026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:63548419--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)4202026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:63548421--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)4222026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:635484232026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:635484242026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:635484252026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:63548426--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)4272026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:63548428--- PASS: TestDumpPathWriterError (0.06s)4292026/10/10 19:01:46 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:63548430--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)431--- PASS: TestDumpPathSingleFile (0.06s)432--- PASS: TestCaseHackSuffix (0.06s)433--- PASS: TestDumpPathMatchesNix (0.09s)434--- PASS: TestStreamPushBatchesUnderLoad (0.10s)435--- PASS: TestUploadMultipart_PartsInParallel (0.62s)436--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)437PASS438Running server tests...439The files belonging to this database system will be owned by user "_tribuchetbld7".440This user must also own the server process.441442The database cluster will be initialized with locale "C".443The default database encoding has accordingly been set to "SQL_ASCII".444The default text search configuration will be set to "english".445446Data page checksums are enabled.447448creating directory /private/var/tb/7/scratch/0e971e34819014b9/build/postgres1378551305/data ... ok449creating subdirectories ... ok450selecting dynamic shared memory implementation ... posix451selecting default "max_connections" ... 100452selecting default "shared_buffers" ... 128MB453selecting default time zone ... UTC454creating configuration files ... ok455running bootstrap script ... ok456performing post-bootstrap initialization ... ok457syncing data to disk ... ok458459initdb: warning: enabling "trust" authentication for local connections460initdb: 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.461462Success. You can now start the database server using:463464 pg_ctl -D /private/var/tb/7/scratch/0e971e34819014b9/build/postgres1378551305/data -l logfile start465466/private/var/tb/7/scratch/0e971e34819014b9/build/postgres1378551305:5432 - no response4672026-10-10 19:01:48.069 UTC [97836] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4682026-10-10 19:01:48.069 UTC [97836] LOG: listening on Unix socket "/private/var/tb/7/scratch/0e971e34819014b9/build/postgres1378551305/.s.PGSQL.5432"4692026-10-10 19:01:48.071 UTC [97843] LOG: database system was shut down at 2026-10-10 19:01:48 UTC4702026-10-10 19:01:48.072 UTC [97836] LOG: database system is ready to accept connections471/private/var/tb/7/scratch/0e971e34819014b9/build/postgres1378551305:5432 - accepting connections472{"timestamp":"2026-10-10T19:01:48.287878Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"c487d5af-87c6-422c-a7ed-badd44b76a97","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}473=== RUN TestService_AuthMiddleware474=== PAUSE TestService_AuthMiddleware475=== RUN TestService_AuthMiddleware_MTLSProxyHeader476=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader477=== RUN TestService_AuthMiddleware_MTLSBoundSubjects478=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects479=== RUN TestService_ReadAuthMiddleware480=== PAUSE TestService_ReadAuthMiddleware481=== RUN TestService_AuthMiddleware_OIDC482=== PAUSE TestService_AuthMiddleware_OIDC483=== RUN TestService_RequireScope_OIDC484=== PAUSE TestService_RequireScope_OIDC485=== RUN TestService_ReadScope_PublicByDefault486=== PAUSE TestService_ReadScope_PublicByDefault487=== RUN TestCacheConfigHandler488=== PAUSE TestCacheConfigHandler489=== RUN TestCacheStatsHandler490=== PAUSE TestCacheStatsHandler491=== RUN TestClientCADerivations492=== PAUSE TestClientCADerivations493=== RUN TestClientErrorHandling494=== PAUSE TestClientErrorHandling495=== RUN TestClientIntegration496=== PAUSE TestClientIntegration497=== RUN TestClientMultipleUploads498=== PAUSE TestClientMultipleUploads499=== RUN TestClientWithDependencies500=== PAUSE TestClientWithDependencies501=== RUN TestClientSharedPathCommittedMidPush502=== PAUSE TestClientSharedPathCommittedMidPush503=== RUN TestPinProtectsFromGC504=== PAUSE TestPinProtectsFromGC505=== RUN TestClientPushesUseOnePush506=== PAUSE TestClientPushesUseOnePush507=== RUN TestClientFallsBackToClosures508=== PAUSE TestClientFallsBackToClosures509=== RUN TestDeleteClosuresRacingPins510=== PAUSE TestDeleteClosuresRacingPins511=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock512=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock513=== RUN TestResolveDBConnectionString514=== PAUSE TestResolveDBConnectionString515=== RUN TestConnectWaitsForAPeerMigration516=== PAUSE TestConnectWaitsForAPeerMigration517=== RUN TestLeadElectsOneAndHandsOver518=== PAUSE TestLeadElectsOneAndHandsOver519=== RUN TestLeadIncumbentWinsAfterRestart5202026/10/10 19:01:48 INFO lead: acquired remote=192.0.2.1:12345212026/10/10 19:01:49 INFO lead: released remote=192.0.2.1:12345222026/10/10 19:01:49 INFO lead: acquired remote=192.0.2.1:12345232026/10/10 19:01:50 INFO lead: released remote=192.0.2.1:1234524--- PASS: TestLeadIncumbentWinsAfterRestart (1.91s)525=== RUN TestLeadIncumbentAnnouncesAtOnce526=== PAUSE TestLeadIncumbentAnnouncesAtOnce527=== RUN TestLeadEndsOnShutdown528=== PAUSE TestLeadEndsOnShutdown529=== RUN TestLeadEndsWhenItsConnectionHangs5302026/10/10 19:01:50 INFO lead: acquired remote=192.0.2.1:12345312026-10-10 19:01:51.880 UTC [97881] FATAL: terminating connection due to administrator command5322026/10/10 19:01:52 INFO lead: acquired remote=192.0.2.1:12345332026/10/10 19:01:53 WARN lead: lock connection lost error="timeout: context deadline exceeded"5342026/10/10 19:01:53 INFO lead: released remote=192.0.2.1:12345352026/10/10 19:01:53 INFO lead: released remote=192.0.2.1:1234536--- PASS: TestLeadEndsWhenItsConnectionHangs (2.97s)537=== RUN TestGCAdvisoryLockBlocksConcurrentRun538=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun539=== RUN TestGCBugBareHashReferences540=== PAUSE TestGCBugBareHashReferences541=== RUN TestGCMetrics542=== PAUSE TestGCMetrics543=== RUN TestPushDedupSurvivesConcurrentGC544=== PAUSE TestPushDedupSurvivesConcurrentGC545=== RUN TestDeduplicatedObjectsRecordedAsPending546=== PAUSE TestDeduplicatedObjectsRecordedAsPending547=== RUN TestGCSweepSkipsPendingObjects548=== PAUSE TestGCSweepSkipsPendingObjects549=== RUN TestTombstonedObjectOfferedWithoutWaiting550=== PAUSE TestTombstonedObjectOfferedWithoutWaiting551=== RUN TestGCSweepDeliversEachKeyOnce552=== PAUSE TestGCSweepDeliversEachKeyOnce553=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection554=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection555=== RUN TestForceGCDuringPushOffersSweptObject556=== PAUSE TestForceGCDuringPushOffersSweptObject557=== RUN TestFailedS3DeleteKeepsTombstone558=== PAUSE TestFailedS3DeleteKeepsTombstone559=== RUN TestSweepSkipsRowsLockedByPush560=== PAUSE TestSweepSkipsRowsLockedByPush561=== RUN TestRegisterCompletedObjectNeedsPendingRow562=== PAUSE TestRegisterCompletedObjectNeedsPendingRow563=== RUN TestGetExistingObjectsLocksRows564=== PAUSE TestGetExistingObjectsLocksRows565=== RUN TestSweepRechecksPendingAfterLocking566=== PAUSE TestSweepRechecksPendingAfterLocking567=== RUN TestPushWaitsForSweepHoldingRow568=== PAUSE TestPushWaitsForSweepHoldingRow569=== RUN TestCommitRacingPendingCleanupKeepsObjects570=== PAUSE TestCommitRacingPendingCleanupKeepsObjects571=== RUN TestGCEndsOnShutdown572=== PAUSE TestGCEndsOnShutdown573=== RUN TestGCTaskStore_StartNew574=== PAUSE TestGCTaskStore_StartNew575=== RUN TestGCTaskStore_DeduplicateSameParams576=== PAUSE TestGCTaskStore_DeduplicateSameParams577=== RUN TestGCTaskStore_ConflictDifferentParams578=== PAUSE TestGCTaskStore_ConflictDifferentParams579=== RUN TestGCTaskStore_GetEmpty580=== PAUSE TestGCTaskStore_GetEmpty581=== RUN TestGCTaskStore_GetReturnsLatest582=== PAUSE TestGCTaskStore_GetReturnsLatest583=== RUN TestGCTaskStore_CompletedAllowsNewTask584=== PAUSE TestGCTaskStore_CompletedAllowsNewTask585=== RUN TestGCTaskStore_PhaseUpdates586=== PAUSE TestGCTaskStore_PhaseUpdates587=== RUN TestGCTaskStore_Fail588=== PAUSE TestGCTaskStore_Fail589=== RUN TestGracefulShutdownDrainsInflight590=== PAUSE TestGracefulShutdownDrainsInflight591=== RUN TestService_healthCheckHandler592=== PAUSE TestService_healthCheckHandler593=== RUN TestService_readinessHandler594=== PAUSE TestService_readinessHandler595=== RUN TestGenerateLandingPage596=== PAUSE TestGenerateLandingPage597=== RUN TestCacheConfigHandlerMaxNarSize598=== PAUSE TestCacheConfigHandlerMaxNarSize599=== RUN TestCreatePendingClosureRejectsOversizedNAR600=== PAUSE TestCreatePendingClosureRejectsOversizedNAR601=== RUN TestNARDeduplicationMetadataUploadBug602=== PAUSE TestNARDeduplicationMetadataUploadBug603=== RUN TestMetricsInventory604=== PAUSE TestMetricsInventory605=== RUN TestMetricsCommit606=== PAUSE TestMetricsCommit607=== RUN TestService_NativeMTLS608=== PAUSE TestService_NativeMTLS609=== RUN TestServerTLSConfig610=== PAUSE TestServerTLSConfig611=== RUN TestMultipartCleanup612=== PAUSE TestMultipartCleanup613=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded614=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded615=== RUN TestPendingCleanupUsesOneCutoff616=== PAUSE TestPendingCleanupUsesOneCutoff617=== RUN TestObjectStatsTrigger618=== PAUSE TestObjectStatsTrigger619=== RUN TestObjectStatsLargeCommit620=== PAUSE TestObjectStatsLargeCommit621=== RUN TestOrphanedObjectsGC622=== PAUSE TestOrphanedObjectsGC623=== RUN TestOrphanedObjectsGCStressTest624=== PAUSE TestOrphanedObjectsGCStressTest625=== RUN TestCreatePin_ReservedPins626=== PAUSE TestCreatePin_ReservedPins627=== RUN TestPresentReportsOnlyClosureRoots628=== PAUSE TestPresentReportsOnlyClosureRoots629=== RUN TestPresentRefreshesOnlyStaleClosures630=== PAUSE TestPresentRefreshesOnlyStaleClosures631=== RUN TestPresentNotReportedWhileGCDeletesClosure632=== PAUSE TestPresentNotReportedWhileGCDeletesClosure633=== RUN TestParseSingleRange634=== PAUSE TestParseSingleRange635=== RUN TestProxyHeadersOnlyTrustedOnSocket6362026/10/10 19:01:53 INFO Starting HTTP server address=127.0.0.1:636576372026/10/10 19:01:53 INFO Starting HTTP server address=proxy.sock6382026/10/10 19:01:53 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6392026/10/10 19:01:53 INFO Shutdown signal received, draining in-flight requests timeout=10s640--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)641=== RUN TestIsValidCachePath642=== PAUSE TestIsValidCachePath643=== RUN TestReadProxyNarinfo644=== PAUSE TestReadProxyNarinfo645=== RUN TestReadProxyNarinfoAlreadyDecompressed646=== PAUSE TestReadProxyNarinfoAlreadyDecompressed647=== RUN TestReadProxyContentNegotiation648=== PAUSE TestReadProxyContentNegotiation649=== RUN TestReadProxyNarStreaming650=== PAUSE TestReadProxyNarStreaming651=== RUN TestReadProxy404652=== PAUSE TestReadProxy404653=== RUN TestReadProxyInvalidPath654=== PAUSE TestReadProxyInvalidPath655=== RUN TestReadProxyHead656=== PAUSE TestReadProxyHead657=== RUN TestReadProxyOutlastsServerWriteTimeout658=== PAUSE TestReadProxyOutlastsServerWriteTimeout659=== RUN TestReadProxyConditionalGet660=== PAUSE TestReadProxyConditionalGet661=== RUN TestReadProxyRootRedirectsToIndexHTML662=== PAUSE TestReadProxyRootRedirectsToIndexHTML663=== RUN TestReadProxyDisabled664=== PAUSE TestReadProxyDisabled665=== RUN TestReadRedirectNar666=== PAUSE TestReadRedirectNar667=== RUN TestReadRedirectKeepsNarinfoProxied668=== PAUSE TestReadRedirectKeepsNarinfoProxied669=== RUN TestReadProxyRangeRequest670=== PAUSE TestReadProxyRangeRequest671=== RUN TestReadRedirectUsesPublicS3URL672=== PAUSE TestReadRedirectUsesPublicS3URL673=== RUN TestPush_OverlappingRootsStoreOneRowPerKey674=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey675=== RUN TestPush_CompleteCommitsEveryRoot676=== PAUSE TestPush_CompleteCommitsEveryRoot677=== RUN TestPush_RepeatedRootCommitsOnce678=== PAUSE TestPush_RepeatedRootCommitsOnce679=== RUN TestPush_CompleteWaitsForCleanupOfThePush680=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush681=== RUN TestPush_RootsAreLockedInByteOrder682=== PAUSE TestPush_RootsAreLockedInByteOrder683=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit684=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit685=== RUN TestPush_RejectsBadRequests686=== PAUSE TestPush_RejectsBadRequests687=== RUN TestPush_SignsNarinfosOfItsPendingObjects688=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects689=== RUN TestRedundantMultipartUpload690=== PAUSE TestRedundantMultipartUpload691=== RUN TestCompleteMultipartUpload_ErrorButObjectExists692=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists693=== RUN TestCompletedNarNotReofferedAcrossClosures694=== PAUSE TestCompletedNarNotReofferedAcrossClosures695=== RUN TestPresignedUploadRegisteredBeforeCommit696=== PAUSE TestPresignedUploadRegisteredBeforeCommit697=== RUN TestService_Rustfstest698=== PAUSE TestService_Rustfstest699=== RUN TestParseSize700=== PAUSE TestParseSize701=== RUN TestSkippedUploadsHandler702=== PAUSE TestSkippedUploadsHandler703=== RUN TestSystemdListenerNotActivated704--- PASS: TestSystemdListenerNotActivated (0.00s)705=== RUN TestWatchdogBeatsWhenHealthy706--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)707=== RUN TestWatchdogSkipsWhenUnhealthy7082026/10/10 19:01:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7092026/10/10 19:01:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7102026/10/10 19:01:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7112026/10/10 19:01:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7122026/10/10 19:01:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7132026/10/10 19:01:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7142026/10/10 19:01:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7152026/10/10 19:01:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7162026/10/10 19:01:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7172026/10/10 19:01:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"718--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)719=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle720=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle721=== RUN TestProxyWriteTimeout722=== PAUSE TestProxyWriteTimeout723=== RUN TestPendingClosureWriteTimeout724=== PAUSE TestPendingClosureWriteTimeout725=== RUN TestIsValidUploadKey726=== PAUSE TestIsValidUploadKey727=== RUN TestUploadHandlersRejectInvalidKeys728=== PAUSE TestUploadHandlersRejectInvalidKeys729=== RUN TestUploadHandlersRejectOversizedBody730=== PAUSE TestUploadHandlersRejectOversizedBody731=== RUN TestService_cleanupPendingClosuresHandler732=== PAUSE TestService_cleanupPendingClosuresHandler733=== RUN TestService_createPendingClosureHandler734=== PAUSE TestService_createPendingClosureHandler735=== RUN TestService_verifyS3Integrity736=== PAUSE TestService_verifyS3Integrity737=== RUN TestCompleteMultipartUnregistered738=== PAUSE TestCompleteMultipartUnregistered739=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT740=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT741=== CONT TestReadRedirectNar742=== CONT TestService_AuthMiddleware743=== CONT TestReadProxyDisabled744=== CONT TestReadProxyRootRedirectsToIndexHTML745=== CONT TestReadProxyConditionalGet746=== CONT TestReadProxyOutlastsServerWriteTimeout747=== CONT TestReadProxyHead748=== CONT TestReadProxyInvalidPath749=== CONT TestReadProxy404750=== CONT TestReadProxyNarStreaming751=== CONT TestReadProxyContentNegotiation752=== CONT TestReadProxyNarinfoAlreadyDecompressed753=== CONT TestPresignedUploadRegisteredBeforeCommit754=== CONT TestReadProxyNarinfo755=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT756=== CONT TestIsValidCachePath757=== CONT TestCompleteMultipartUnregistered758=== CONT TestService_verifyS3Integrity759=== RUN TestIsValidCachePath/narinfo760=== CONT TestService_createPendingClosureHandler761=== CONT TestService_cleanupPendingClosuresHandler762=== CONT TestUploadHandlersRejectOversizedBody763=== CONT TestUploadHandlersRejectInvalidKeys764=== CONT TestIsValidUploadKey765=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info766=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info767=== CONT TestParseSingleRange768=== RUN TestIsValidUploadKey/narinfo769=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal770=== RUN TestParseSingleRange/none771=== PAUSE TestIsValidUploadKey/narinfo772=== RUN TestIsValidUploadKey/nar_zst773=== PAUSE TestIsValidCachePath/narinfo774=== PAUSE TestParseSingleRange/none775=== RUN TestParseSingleRange/unknown_unit776=== PAUSE TestParseSingleRange/unknown_unit777=== RUN TestParseSingleRange/multi-range_ignored778=== PAUSE TestParseSingleRange/multi-range_ignored779=== RUN TestParseSingleRange/malformed_no_dash780=== PAUSE TestParseSingleRange/malformed_no_dash781=== RUN TestParseSingleRange/malformed_both_empty782=== PAUSE TestParseSingleRange/malformed_both_empty783=== RUN TestParseSingleRange/malformed_end_before_start784=== PAUSE TestIsValidUploadKey/nar_zst785=== PAUSE TestParseSingleRange/malformed_end_before_start786=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars787=== RUN TestParseSingleRange/closed788=== PAUSE TestParseSingleRange/closed789=== RUN TestIsValidUploadKey/nar_xz790=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars791=== PAUSE TestIsValidUploadKey/nar_xz792=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal793=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key794=== RUN TestIsValidUploadKey/nar_plain795=== RUN TestParseSingleRange/open-ended796=== RUN TestIsValidCachePath/nar_zst797=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key798=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key799=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key800=== PAUSE TestParseSingleRange/open-ended801=== RUN TestParseSingleRange/end_clamped_to_size802=== PAUSE TestParseSingleRange/end_clamped_to_size803=== RUN TestParseSingleRange/suffix804=== PAUSE TestParseSingleRange/suffix805=== RUN TestParseSingleRange/suffix_exceeds_size806=== PAUSE TestParseSingleRange/suffix_exceeds_size807=== RUN TestParseSingleRange/single_byte808=== PAUSE TestParseSingleRange/single_byte809=== RUN TestParseSingleRange/start_past_EOF810=== PAUSE TestParseSingleRange/start_past_EOF811=== RUN TestParseSingleRange/start_far_past_EOF812=== PAUSE TestParseSingleRange/start_far_past_EOF813=== CONT TestPendingClosureWriteTimeout814=== RUN TestPendingClosureWriteTimeout/empty815=== PAUSE TestPendingClosureWriteTimeout/empty816=== RUN TestPendingClosureWriteTimeout/400_objects817=== PAUSE TestPendingClosureWriteTimeout/400_objects818=== RUN TestPendingClosureWriteTimeout/670k_objects819=== PAUSE TestPendingClosureWriteTimeout/670k_objects820=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline821=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline822=== PAUSE TestIsValidCachePath/nar_zst823=== RUN TestIsValidCachePath/nar_xz824=== PAUSE TestIsValidCachePath/nar_xz825=== RUN TestIsValidCachePath/nar_bz2826=== PAUSE TestIsValidCachePath/nar_bz2827=== RUN TestIsValidCachePath/nar_uncompressed828=== PAUSE TestIsValidCachePath/nar_uncompressed829=== RUN TestIsValidCachePath/ls830=== PAUSE TestIsValidCachePath/ls831=== RUN TestIsValidCachePath/log832=== PAUSE TestIsValidCachePath/log833=== RUN TestIsValidCachePath/realisation834=== PAUSE TestIsValidCachePath/realisation835=== RUN TestIsValidCachePath/nix-cache-info836=== PAUSE TestIsValidCachePath/nix-cache-info837=== RUN TestIsValidCachePath/index.html838=== PAUSE TestIsValidCachePath/index.html839=== RUN TestIsValidCachePath/traversal_parent840=== PAUSE TestIsValidCachePath/traversal_parent841=== RUN TestIsValidCachePath/traversal_in_middle842=== PAUSE TestIsValidCachePath/traversal_in_middle843=== RUN TestIsValidCachePath/invalid_char_e844=== PAUSE TestIsValidCachePath/invalid_char_e845=== RUN TestIsValidCachePath/invalid_char_u846=== PAUSE TestIsValidCachePath/invalid_char_u847=== RUN TestIsValidCachePath/random_path848=== PAUSE TestIsValidCachePath/random_path849=== RUN TestIsValidCachePath/empty850=== PAUSE TestIsValidCachePath/empty851=== RUN TestIsValidCachePath/leading_slash852=== PAUSE TestIsValidCachePath/leading_slash853=== RUN TestIsValidCachePath/wrong_extension854=== PAUSE TestIsValidCachePath/wrong_extension855=== RUN TestIsValidCachePath/short_hash856=== PAUSE TestIsValidCachePath/short_hash857=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle858=== CONT TestProxyWriteTimeout859=== RUN TestProxyWriteTimeout/narinfo860=== PAUSE TestProxyWriteTimeout/narinfo861=== RUN TestProxyWriteTimeout/1_GiB_nar862=== PAUSE TestProxyWriteTimeout/1_GiB_nar863=== RUN TestProxyWriteTimeout/10_GiB_nar864=== PAUSE TestProxyWriteTimeout/10_GiB_nar865=== RUN TestProxyWriteTimeout/unknown_size866=== PAUSE TestProxyWriteTimeout/unknown_size867=== CONT TestPresentRefreshesOnlyStaleClosures868=== CONT TestPresentNotReportedWhileGCDeletesClosure869=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale870=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale871=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh872=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh873=== PAUSE TestIsValidUploadKey/nar_plain874=== RUN TestIsValidUploadKey/listing875=== PAUSE TestIsValidUploadKey/listing876=== RUN TestIsValidUploadKey/build_log877=== PAUSE TestIsValidUploadKey/build_log878=== RUN TestIsValidUploadKey/build_log_home-manager_file879=== PAUSE TestIsValidUploadKey/build_log_home-manager_file880=== RUN TestIsValidUploadKey/build_log_plus_in_name881=== PAUSE TestIsValidUploadKey/build_log_plus_in_name882=== RUN TestIsValidUploadKey/build_log_question_mark883=== PAUSE TestIsValidUploadKey/build_log_question_mark884=== RUN TestIsValidUploadKey/build_log_equals885=== PAUSE TestIsValidUploadKey/build_log_equals886=== RUN TestIsValidUploadKey/realisation887=== PAUSE TestIsValidUploadKey/realisation888=== RUN TestIsValidUploadKey/realisation_plus_in_output889=== PAUSE TestIsValidUploadKey/realisation_plus_in_output890=== RUN TestIsValidUploadKey/nix-cache-info891=== PAUSE TestIsValidUploadKey/nix-cache-info892=== RUN TestIsValidUploadKey/index.html893=== PAUSE TestIsValidUploadKey/index.html894=== RUN TestIsValidUploadKey/narinfo_key,_nar_type895=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type896=== RUN TestIsValidUploadKey/nar_key,_narinfo_type897=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type898=== RUN TestIsValidUploadKey/listing_key,_narinfo_type899=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type900=== RUN TestIsValidUploadKey/traversal901=== PAUSE TestIsValidUploadKey/traversal902=== RUN TestIsValidUploadKey/traversal_nar903=== PAUSE TestIsValidUploadKey/traversal_nar904=== RUN TestIsValidUploadKey/absolute905=== PAUSE TestIsValidUploadKey/absolute906=== RUN TestIsValidUploadKey/empty_key907=== PAUSE TestIsValidUploadKey/empty_key908=== RUN TestIsValidUploadKey/unknown_type909=== PAUSE TestIsValidUploadKey/unknown_type910=== CONT TestSkippedUploadsHandler9112026/10/10 19:01:53 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000912=== CONT TestPresentReportsOnlyClosureRoots913--- PASS: TestSkippedUploadsHandler (0.00s)914=== CONT TestParseSize915--- PASS: TestParseSize (0.00s)916=== CONT TestService_Rustfstest917=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts918=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts919=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure920=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure921=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart922=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart923=== CONT TestCreatePin_ReservedPins9242026/10/10 19:01:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63660/oidc925--- PASS: TestReadProxyInvalidPath (0.99s)926=== CONT TestForceGCDuringPushOffersSweptObject927=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows928=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows929=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check930=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check931=== CONT TestFailedS3DeleteKeepsTombstone932--- PASS: TestReadRedirectNar (1.39s)933=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection934--- PASS: TestReadProxyDisabled (1.68s)935=== CONT TestGCSweepDeliversEachKeyOnce9362026/10/10 19:01:55 INFO Received uploads request method=POST path=/api/pending_closures9372026/10/10 19:01:56 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"938--- PASS: TestService_AuthMiddleware (2.43s)939=== CONT TestTombstonedObjectOfferedWithoutWaiting9402026/10/10 19:01:56 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>941--- PASS: TestReadProxyNarinfo (2.87s)942=== CONT TestService_healthCheckHandler9432026/10/10 19:01:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9442026/10/10 19:01:56 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst945--- PASS: TestCompleteMultipartUnregistered (3.09s)946=== CONT TestGracefulShutdownDrainsInflight9472026/10/10 19:01:56 INFO Starting HTTP server address=127.0.0.1:636829482026/10/10 19:01:56 INFO Shutdown signal received, draining in-flight requests timeout=10s949--- PASS: TestGracefulShutdownDrainsInflight (0.08s)950=== CONT TestOrphanedObjectsGCStressTest951--- PASS: TestReadProxyRootRedirectsToIndexHTML (3.76s)952=== CONT TestGCTaskStore_Fail953--- PASS: TestGCTaskStore_Fail (0.00s)954=== CONT TestOrphanedObjectsGC9552026/10/10 19:01:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9562026/10/10 19:01:57 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZjU1NDkzN2EtYjg3Mi00MTJhLTg3ZDQtZGU1YmI4YmE3MmVhLmRlYzhhMGVmLWQwNTQtNDdmNi05MTM2LWRjNDM5MjBlY2U1Y3gxNzkxNjU4OTE1ODI3NDc4MDAw parts=109572026/10/10 19:01:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9582026/10/10 19:01:57 INFO Completed upload id=1 objects=2 duration=18.784833ms9592026/10/10 19:01:57 INFO Received uploads request method=POST path=/api/pending_closures9602026/10/10 19:01:57 INFO Received uploads request method=POST path=/api/pending_closures9612026/10/10 19:01:57 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9622026/10/10 19:01:57 WARN Found objects in DB but missing from S3, will re-upload count=1963--- PASS: TestService_verifyS3Integrity (3.90s)964=== CONT TestGCTaskStore_PhaseUpdates965--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)966=== CONT TestObjectStatsLargeCommit9672026/10/10 19:01:57 INFO Received uploads request method=POST path=/api/pending_closures9682026/10/10 19:01:57 INFO Received uploads request method=POST path=/api/pending_closures9692026/10/10 19:01:57 INFO Received uploads request method=POST path=/api/pending_closures970--- PASS: TestReadProxyHead (4.37s)971=== CONT TestObjectStatsTrigger972--- PASS: TestReadProxyConditionalGet (4.68s)973=== CONT TestGCSweepSkipsPendingObjects974--- PASS: TestReadProxyNarStreaming (4.99s)975=== CONT TestDeduplicatedObjectsRecordedAsPending976--- PASS: TestReadProxy404 (5.40s)977=== CONT TestGCTaskStore_CompletedAllowsNewTask978--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)979=== CONT TestGCTaskStore_GetReturnsLatest980--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)981=== CONT TestPendingCleanupUsesOneCutoff982--- PASS: TestReadProxyNarinfoAlreadyDecompressed (5.62s)983=== CONT TestGCTaskStore_GetEmpty984--- PASS: TestGCTaskStore_GetEmpty (0.00s)985=== CONT TestPushDedupSurvivesConcurrentGC9862026/10/10 19:01:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9872026/10/10 19:01:59 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZjU1NDkzN2EtYjg3Mi00MTJhLTg3ZDQtZGU1YmI4YmE3MmVhLmZmMDQwMWFjLTIxY2UtNGNjMS1iMGVhLWU0YjVhODk0NjFkN3gxNzkxNjU4OTE3NzY1MDMzMDAw parts=109882026/10/10 19:01:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9892026/10/10 19:01:59 INFO Completed upload id=1 objects=2 duration=26.322083ms9902026/10/10 19:01:59 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009912026/10/10 19:01:59 INFO Received uploads request method=POST path=/api/pending_closures9922026/10/10 19:01:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures9932026/10/10 19:01:59 INFO Aborted multipart uploads count=0 kept=09942026/10/10 19:01:59 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=09952026/10/10 19:01:59 INFO Vacuumed table table=pending_closures9962026/10/10 19:01:59 INFO Vacuumed table table=pending_objects9972026/10/10 19:01:59 INFO Vacuumed table table=multipart_uploads9982026/10/10 19:01:59 INFO Vacuumed table table=closures9992026/10/10 19:01:59 INFO Vacuumed table table=objects1000--- PASS: TestReadProxyContentNegotiation (6.02s)1001=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded10022026/10/10 19:01:59 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001003--- PASS: TestService_createPendingClosureHandler (6.04s)1004=== CONT TestGCTaskStore_ConflictDifferentParams1005--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1006=== CONT TestGCMetrics10072026/10/10 19:01:59 INFO Received uploads request method=POST path=/api/pending_closures1008--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (6.30s)1009=== CONT TestMultipartCleanup10102026/10/10 19:02:00 INFO Received uploads request method=POST path=/api/pending_closures10112026/10/10 19:02:00 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10122026/10/10 19:02:00 INFO Received uploads request method=POST path=/api/pending_closures1013--- PASS: TestPresignedUploadRegisteredBeforeCommit (6.61s)1014=== CONT TestServerTLSConfig1015=== RUN TestServerTLSConfig/no_client_CA1016=== PAUSE TestServerTLSConfig/no_client_CA1017=== RUN TestServerTLSConfig/missing_CA_file1018=== PAUSE TestServerTLSConfig/missing_CA_file1019=== RUN TestServerTLSConfig/not_a_PEM_file1020=== PAUSE TestServerTLSConfig/not_a_PEM_file1021=== CONT TestGCTaskStore_DeduplicateSameParams1022--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1023=== CONT TestGCBugBareHashReferences10242026/10/10 19:02:00 INFO Received cleanup request method=DELETE path=/api/pending_closures10252026/10/10 19:02:00 INFO Aborted multipart uploads count=0 kept=010262026/10/10 19:02:00 INFO Received uploads request method=POST path=/api/pending_closures10272026/10/10 19:02:00 INFO Received cleanup request method=DELETE path=/api/pending_closures10282026/10/10 19:02:00 INFO Aborted multipart uploads count=1 kept=010292026/10/10 19:02:00 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10302026-10-10 19:02:00.579 UTC [97958] ERROR: Closure does not exist: id=110312026-10-10 19:02:00.579 UTC [97958] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10322026-10-10 19:02:00.579 UTC [97958] STATEMENT: -- name: CommitPendingClosure :one1033 SELECT commit_pending_closure($1::bigint)::bigint1034 1035--- PASS: TestService_cleanupPendingClosuresHandler (6.90s)1036=== CONT TestGCTaskStore_StartNew1037--- PASS: TestGCTaskStore_StartNew (0.00s)1038=== CONT TestService_NativeMTLS1039--- PASS: TestPresentReportsOnlyClosureRoots (7.07s)1040=== CONT TestGCEndsOnShutdown1041=== RUN TestGCEndsOnShutdown/before_the_run1042=== PAUSE TestGCEndsOnShutdown/before_the_run1043=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1044=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1045=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1046=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1047=== CONT TestMetricsCommit1048--- PASS: TestPresentRefreshesOnlyStaleClosures (7.44s)1049=== CONT TestCommitRacingPendingCleanupKeepsObjects1050--- PASS: TestReadProxyOutlastsServerWriteTimeout (7.63s)1051=== CONT TestMetricsInventory10522026/10/10 19:02:01 INFO Received uploads request method=POST path=/api/pending_closures1053--- PASS: TestService_Rustfstest (8.09s)1054=== CONT TestGCAdvisoryLockBlocksConcurrentRun10552026/10/10 19:02:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10562026/10/10 19:02:02 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10572026/10/10 19:02:02 WARN Refused reserved pin name=worker-x86_64-linux10582026/10/10 19:02:02 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10592026/10/10 19:02:02 INFO Received create pin request method=POST path=/api/pins/my-app10602026/10/10 19:02:02 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1061--- PASS: TestCreatePin_ReservedPins (8.50s)1062=== CONT TestNARDeduplicationMetadataUploadBug10632026/10/10 19:02:02 INFO Received uploads request method=POST path=/api/pending_closures1064--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.83s)1065=== CONT TestLeadEndsOnShutdown10662026/10/10 19:02:02 INFO Received uploads request method=POST path=/api/pending_closures10672026/10/10 19:02:03 INFO Aborted multipart uploads count=0 kept=010682026/10/10 19:02:03 WARN Force mode enabled - objects will be deleted immediately without grace period10692026/10/10 19:02:03 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."10702026/10/10 19:02:03 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1071--- PASS: TestFailedS3DeleteKeepsTombstone (8.75s)1072=== CONT TestLeadIncumbentAnnouncesAtOnce10732026/10/10 19:02:03 INFO Aborted multipart uploads count=0 kept=010742026/10/10 19:02:03 WARN Force mode enabled - objects will be deleted immediately without grace period10752026/10/10 19:02:03 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=010762026/10/10 19:02:03 INFO Vacuumed table table=pending_closures10772026/10/10 19:02:03 INFO Vacuumed table table=pending_objects10782026/10/10 19:02:03 INFO Vacuumed table table=multipart_uploads10792026/10/10 19:02:03 INFO Vacuumed table table=closures10802026/10/10 19:02:03 INFO Vacuumed table table=objects1081--- PASS: TestGCSweepDeliversEachKeyOnce (8.52s)1082=== CONT TestLeadElectsOneAndHandsOver10832026/10/10 19:02:03 INFO Received uploads request method=POST path=/api/pending_closures1084--- PASS: TestTombstonedObjectOfferedWithoutWaiting (7.86s)1085=== CONT TestPushWaitsForSweepHoldingRow1086--- PASS: TestService_healthCheckHandler (7.65s)1087=== CONT TestSweepRechecksPendingAfterLocking1088--- PASS: TestObjectStatsTrigger (7.80s)1089=== CONT TestGetExistingObjectsLocksRows10902026/10/10 19:02:06 INFO Received uploads request method=POST path=/api/pending_closures10912026/10/10 19:02:06 INFO Aborted multipart uploads count=0 kept=010922026/10/10 19:02:06 WARN Force mode enabled - objects will be deleted immediately without grace period10932026/10/10 19:02:06 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=01094=== NAME TestOrphanedObjectsGC1095 orphaned_objects_gc_test.go:287: GC Test Summary:1096 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1097 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1098 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1099 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1100 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1101--- PASS: TestOrphanedObjectsGC (8.79s)1102=== CONT TestCreatePendingClosureRejectsOversizedNAR11032026/10/10 19:02:06 INFO Received uploads request method=POST path=/api/pending_closures1104--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1105=== CONT TestConnectWaitsForAPeerMigration11062026/10/10 19:02:06 INFO Vacuumed table table=pending_closures11072026/10/10 19:02:06 INFO Vacuumed table table=pending_objects11082026/10/10 19:02:06 INFO Vacuumed table table=multipart_uploads11092026/10/10 19:02:06 INFO Vacuumed table table=closures11102026/10/10 19:02:06 INFO Vacuumed table table=objects1111--- PASS: TestGCSweepSkipsPendingObjects (7.99s)1112=== CONT TestRegisterCompletedObjectNeedsPendingRow11132026/10/10 19:02:06 INFO Received uploads request method=POST path=/api/pending_closures11142026/10/10 19:02:06 WARN Rate limiter enabled after throttle name=s3-test rate=511152026/10/10 19:02:06 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1116=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1117 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101118 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001119--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (12.69s)1120=== CONT TestCacheConfigHandlerMaxNarSize1121--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1122=== CONT TestResolveDBConnectionString1123=== RUN TestResolveDBConnectionString/flag_wins1124=== PAUSE TestResolveDBConnectionString/flag_wins1125=== RUN TestResolveDBConnectionString/file_when_flag_empty1126=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1127=== RUN TestResolveDBConnectionString/missing_file_is_an_error1128=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1129=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1130=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1131=== RUN TestResolveDBConnectionString/nothing_configured1132=== PAUSE TestResolveDBConnectionString/nothing_configured1133=== CONT TestSweepSkipsRowsLockedByPush1134--- PASS: TestDeduplicatedObjectsRecordedAsPending (7.77s)1135=== CONT TestGenerateLandingPage1136--- PASS: TestGenerateLandingPage (0.00s)1137=== CONT TestService_readinessHandler11382026/10/10 19:02:06 INFO Received uploads request method=POST path=/api/pending_closures11392026/10/10 19:02:06 INFO Received uploads request method=POST path=/api/pending_closures11402026/10/10 19:02:06 INFO Received cleanup request method=DELETE path=/api/pending_closures11412026/10/10 19:02:07 INFO Received uploads request method=POST path=/api/pending_closures11422026/10/10 19:02:07 INFO Aborted multipart uploads count=0 kept=011432026/10/10 19:02:07 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=011442026/10/10 19:02:07 INFO Received uploads request method=POST path=/api/pending_closures11452026/10/10 19:02:07 INFO Vacuumed table table=pending_closures11462026/10/10 19:02:07 INFO Vacuumed table table=pending_objects11472026/10/10 19:02:07 INFO Vacuumed table table=multipart_uploads11482026/10/10 19:02:07 INFO Vacuumed table table=closures1149--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (7.90s)1150=== CONT TestPush_RootsAreLockedInByteOrder11512026/10/10 19:02:07 INFO Vacuumed table table=objects11522026/10/10 19:02:07 INFO Aborted multipart uploads count=0 kept=011532026/10/10 19:02:07 WARN Force mode enabled - objects will be deleted immediately without grace period11542026/10/10 19:02:07 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=011552026/10/10 19:02:07 INFO Vacuumed table table=pending_closures11562026/10/10 19:02:07 INFO Vacuumed table table=pending_objects11572026/10/10 19:02:07 INFO Vacuumed table table=multipart_uploads11582026/10/10 19:02:07 INFO Vacuumed table table=closures11592026/10/10 19:02:07 INFO Vacuumed table table=objects1160--- PASS: TestPushDedupSurvivesConcurrentGC (8.40s)1161=== CONT TestPinProtectsFromGC11622026/10/10 19:02:07 INFO Aborted multipart uploads count=0 kept=011632026/10/10 19:02:07 WARN Force mode enabled - objects will be deleted immediately without grace period11642026/10/10 19:02:07 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=011652026/10/10 19:02:07 INFO Vacuumed table table=pending_closures11662026/10/10 19:02:07 INFO Vacuumed table table=pending_objects11672026/10/10 19:02:07 INFO Vacuumed table table=multipart_uploads11682026/10/10 19:02:07 INFO Vacuumed table table=closures11692026/10/10 19:02:07 INFO Vacuumed table table=objects1170--- PASS: TestGCMetrics (8.24s)1171=== CONT TestDeleteClosuresRacingPins11722026/10/10 19:02:08 INFO Received uploads request method=POST path=/api/pending_closures11732026/10/10 19:02:08 INFO Received cleanup request method=DELETE path=/api/pending_closures11742026/10/10 19:02:08 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket43/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""11752026/10/10 19:02:08 INFO Aborted multipart uploads count=0 kept=111762026/10/10 19:02:08 INFO Received cleanup request method=DELETE path=/api/pending_closures11772026/10/10 19:02:08 INFO Aborted multipart uploads count=1 kept=01178--- PASS: TestMultipartCleanup (8.48s)1179=== CONT TestCompletedNarNotReofferedAcrossClosures1180--- PASS: TestGCBugBareHashReferences (8.51s)1181=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock11822026/10/10 19:02:08 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11832026/10/10 19:02:08 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1184--- PASS: TestService_NativeMTLS (8.29s)1185=== CONT TestClientFallsBackToClosures11862026/10/10 19:02:09 INFO Received push request method=POST path=/api/pushes11872026/10/10 19:02:09 INFO Received complete push request method=POST path=/api/pushes/1/complete11882026/10/10 19:02:09 INFO Completed push id=1 objects=4 duration=56.362667ms11892026/10/10 19:02:09 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11902026/10/10 19:02:09 INFO Completed upload id=2 objects=2 duration=559.25µs1191--- PASS: TestMetricsCommit (8.62s)1192=== CONT TestCompleteMultipartUpload_ErrorButObjectExists11932026/10/10 19:02:09 INFO Aborted multipart uploads count=0 kept=011942026/10/10 19:02:09 WARN Force mode enabled - objects will be deleted immediately without grace period11952026/10/10 19:02:09 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=011962026/10/10 19:02:09 INFO Vacuumed table table=pending_closures11972026/10/10 19:02:09 INFO Vacuumed table table=pending_objects11982026/10/10 19:02:09 INFO Vacuumed table table=multipart_uploads11992026/10/10 19:02:09 INFO Vacuumed table table=closures12002026/10/10 19:02:09 INFO Vacuumed table table=objects1201--- PASS: TestCommitRacingPendingCleanupKeepsObjects (8.73s)1202=== CONT TestClientPushesUseOnePush1203--- PASS: TestMetricsInventory (8.69s)1204=== CONT TestClientErrorHandling1205=== RUN TestClientErrorHandling/InvalidStorePath1206=== PAUSE TestClientErrorHandling/InvalidStorePath1207=== RUN TestClientErrorHandling/InvalidAuthToken1208=== PAUSE TestClientErrorHandling/InvalidAuthToken1209=== RUN TestClientErrorHandling/ServerNotAvailable1210=== PAUSE TestClientErrorHandling/ServerNotAvailable1211=== CONT TestRedundantMultipartUpload12122026/10/10 19:02:10 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld7 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1213--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (8.52s)1214=== CONT TestPush_OverlappingRootsStoreOneRowPerKey1215=== NAME TestNARDeduplicationMetadataUploadBug1216 metadata_upload_test.go:48: First store path: /private/var/tb/7/scratch/0e971e34819014b9/build/TestNARDeduplicationMetadataUploadBug2887241540/001/store/ipdl5nv79zyr211pcalzwzi7mfhl11cb-file1.txt12172026/10/10 19:02:10 INFO lead: acquired remote=192.0.2.1:123412182026/10/10 19:02:11 INFO Received push request method=POST path=/api/pushes12192026/10/10 19:02:11 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12202026/10/10 19:02:11 INFO Uploading ipdl5nv79zyr211pcalzwzi7mfhl11cb-file1.txt (160B)12212026/10/10 19:02:11 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12222026/10/10 19:02:11 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12232026/10/10 19:02:11 WARN Failed to register uploaded object key=ipdl5nv79zyr211pcalzwzi7mfhl11cb.ls error="server returned 404: 404 page not found\n"12242026/10/10 19:02:11 INFO Signed narinfos id=1 count=112252026/10/10 19:02:11 INFO Uploading 1 narinfos12262026/10/10 19:02:11 INFO Received complete push request method=POST path=/api/pushes/1/complete12272026/10/10 19:02:11 WARN Failed to register uploaded object key=ipdl5nv79zyr211pcalzwzi7mfhl11cb.narinfo error="server returned 404: 404 page not found\n"12282026/10/10 19:02:11 INFO Completed push id=1 objects=3 duration=38.261791ms12292026/10/10 19:02:11 INFO Upload complete. (211ms)1230 metadata_upload_test.go:54: Retrieved narinfo from S3:1231 StorePath: /private/var/tb/7/scratch/0e971e34819014b9/build/TestNARDeduplicationMetadataUploadBug2887241540/001/store/ipdl5nv79zyr211pcalzwzi7mfhl11cb-file1.txt1232 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1233 Compression: zstd1234 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1235 NarSize: 1601236 References: 1237 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1238 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1239 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1240 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12412026/10/10 19:02:11 INFO lead: acquired remote=192.0.2.1:123412422026/10/10 19:02:11 INFO lead: released remote=192.0.2.1:12341243--- PASS: TestLeadIncumbentAnnouncesAtOnce (7.87s)1244=== CONT TestPush_SignsNarinfosOfItsPendingObjects1245=== NAME TestNARDeduplicationMetadataUploadBug1246 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/7/scratch/0e971e34819014b9/build/TestNARDeduplicationMetadataUploadBug2887241540/001/store/jyh4i32qvrkbn1ffbgjzsgxrvs1h7bmc-file2.txt12472026/10/10 19:02:11 INFO Received push request method=POST path=/api/pushes12482026/10/10 19:02:11 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12492026/10/10 19:02:11 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12502026/10/10 19:02:11 WARN Failed to register uploaded object key=jyh4i32qvrkbn1ffbgjzsgxrvs1h7bmc.ls error="server returned 404: 404 page not found\n"12512026/10/10 19:02:11 INFO Signed narinfos id=2 count=112522026/10/10 19:02:11 INFO Uploading 1 narinfos12532026/10/10 19:02:11 INFO Received complete push request method=POST path=/api/pushes/2/complete12542026/10/10 19:02:11 WARN Failed to register uploaded object key=jyh4i32qvrkbn1ffbgjzsgxrvs1h7bmc.narinfo error="server returned 404: 404 page not found\n"12552026/10/10 19:02:11 INFO Completed push id=2 objects=3 duration=1.012459ms12562026/10/10 19:02:11 INFO Upload complete. (113ms)1257 metadata_upload_test.go:76: Retrieved narinfo from S3:1258 StorePath: /private/var/tb/7/scratch/0e971e34819014b9/build/TestNARDeduplicationMetadataUploadBug2887241540/001/store/jyh4i32qvrkbn1ffbgjzsgxrvs1h7bmc-file2.txt1259 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1260 Compression: zstd1261 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1262 NarSize: 1601263 References: 1264 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1265 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1266 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1267 {"version":1,"root":{"type":"regular","size":44}}1268--- PASS: TestNARDeduplicationMetadataUploadBug (9.27s)1269=== CONT TestClientSharedPathCommittedMidPush12702026/10/10 19:02:11 INFO lead: acquired remote=192.0.2.1:123412712026/10/10 19:02:11 INFO Received uploads request method=POST path=/api/pending_closures12722026/10/10 19:02:12 INFO lead: released remote=192.0.2.1:12341273--- PASS: TestLeadEndsOnShutdown (9.12s)1274=== CONT TestPush_CompleteWaitsForCleanupOfThePush1275=== NAME TestOrphanedObjectsGCStressTest1276 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1277 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion12782026/10/10 19:02:12 INFO Aborted multipart uploads count=0 kept=012792026/10/10 19:02:12 WARN Force mode enabled - objects will be deleted immediately without grace period12802026/10/10 19:02:12 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=012812026/10/10 19:02:12 INFO Vacuumed table table=pending_closures12822026/10/10 19:02:12 INFO Vacuumed table table=pending_objects12832026/10/10 19:02:12 INFO Vacuumed table table=multipart_uploads12842026/10/10 19:02:12 INFO Vacuumed table table=closures12852026/10/10 19:02:12 INFO Vacuumed table table=objects1286--- PASS: TestPushWaitsForSweepHoldingRow (8.46s)1287=== CONT TestPush_RejectsBadRequests1288--- PASS: TestSweepRechecksPendingAfterLocking (8.21s)1289=== CONT TestClientWithDependencies1290--- PASS: TestGetExistingObjectsLocksRows (6.68s)1291=== CONT TestPush_RepeatedRootCommitsOnce1292--- PASS: TestRegisterCompletedObjectNeedsPendingRow (6.40s)1293=== CONT TestClientCADerivations12942026/10/10 19:02:12 INFO lead: released remote=192.0.2.1:123412952026/10/10 19:02:12 INFO lead: acquired remote=192.0.2.1:123412962026/10/10 19:02:12 INFO Aborted multipart uploads count=1 kept=012972026/10/10 19:02:12 INFO Received cleanup request method=DELETE path=/api/pending_closures12982026/10/10 19:02:12 INFO Aborted multipart uploads count=1 kept=01299--- PASS: TestPendingCleanupUsesOneCutoff (13.92s)1300=== CONT TestClientMultipleUploads13012026/10/10 19:02:13 WARN readiness check failed error="closed pool"1302--- PASS: TestService_readinessHandler (6.55s)1303=== CONT TestPush_CompleteCommitsEveryRoot13042026/10/10 19:02:13 INFO Aborted multipart uploads count=0 kept=013052026/10/10 19:02:13 WARN Force mode enabled - objects will be deleted immediately without grace period13062026/10/10 19:02:13 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=013072026/10/10 19:02:13 INFO Vacuumed table table=pending_closures13082026/10/10 19:02:13 INFO Vacuumed table table=pending_objects13092026/10/10 19:02:13 INFO Vacuumed table table=multipart_uploads13102026/10/10 19:02:13 INFO Vacuumed table table=closures13112026/10/10 19:02:13 INFO Vacuumed table table=objects13122026/10/10 19:02:13 INFO Aborted multipart uploads count=0 kept=013132026/10/10 19:02:13 WARN Force mode enabled - objects will be deleted immediately without grace period13142026/10/10 19:02:13 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=013152026/10/10 19:02:13 INFO Vacuumed table table=pending_closures13162026/10/10 19:02:13 INFO Vacuumed table table=pending_objects13172026/10/10 19:02:13 INFO Vacuumed table table=multipart_uploads13182026/10/10 19:02:13 INFO Vacuumed table table=closures13192026/10/10 19:02:13 INFO Received push request method=POST path=/api/pushes13202026/10/10 19:02:13 INFO Vacuumed table table=objects1321--- PASS: TestSweepSkipsRowsLockedByPush (7.17s)1322=== CONT TestClientIntegration13232026-10-10 19:02:13.805 UTC [98097] ERROR: could not obtain lock on row in relation "closures"13242026-10-10 19:02:13.805 UTC [98097] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13252026-10-10 19:02:13.810 UTC [98097] ERROR: could not obtain lock on row in relation "closures"13262026-10-10 19:02:13.810 UTC [98097] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13272026-10-10 19:02:13.810 UTC [98097] ERROR: could not obtain lock on row in relation "closures"13282026-10-10 19:02:13.810 UTC [98097] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13292026-10-10 19:02:13.811 UTC [98097] ERROR: could not obtain lock on row in relation "closures"13302026-10-10 19:02:13.811 UTC [98097] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13312026-10-10 19:02:13.811 UTC [98097] ERROR: could not obtain lock on row in relation "closures"13322026-10-10 19:02:13.811 UTC [98097] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1333--- PASS: TestPush_RootsAreLockedInByteOrder (6.22s)1334=== CONT TestReadProxyRangeRequest13352026/10/10 19:02:13 INFO lead: released remote=192.0.2.1:12341336--- PASS: TestLeadElectsOneAndHandsOver (10.00s)1337=== CONT TestReadRedirectKeepsNarinfoProxied1338--- PASS: TestObjectStatsLargeCommit (16.33s)1339=== CONT TestReadRedirectUsesPublicS3URL1340--- PASS: TestConnectWaitsForAPeerMigration (7.97s)1341=== CONT TestService_AuthMiddleware_OIDC13422026/10/10 19:02:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63788/oidc1343=== NAME TestPinProtectsFromGC1344 client_integration_test.go:731: Pinned store path: /private/var/tb/7/scratch/0e971e34819014b9/build/TestPinProtectsFromGC2270514905/001/store/6b71pfa7v9ha7vr5ikbfrld4jjqqklkn-pinned-file.txt1345 client_integration_test.go:732: Unpinned store path: /private/var/tb/7/scratch/0e971e34819014b9/build/TestPinProtectsFromGC2270514905/001/store/n765cwmnn2g5hi38bsgczarsfxm179y0-unpinned-file.txt13462026/10/10 19:02:14 INFO Received push request method=POST path=/api/pushes13472026/10/10 19:02:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13482026/10/10 19:02:14 INFO Uploading 6b71pfa7v9ha7vr5ikbfrld4jjqqklkn-pinned-file.txt (128B)13492026/10/10 19:02:14 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"13502026/10/10 19:02:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13512026/10/10 19:02:14 WARN Failed to register uploaded object key=6b71pfa7v9ha7vr5ikbfrld4jjqqklkn.ls error="server returned 404: 404 page not found\n"13522026/10/10 19:02:14 INFO Signed narinfos id=1 count=113532026/10/10 19:02:14 INFO Uploading 1 narinfos13542026/10/10 19:02:14 INFO Received complete push request method=POST path=/api/pushes/1/complete13552026/10/10 19:02:14 WARN Failed to register uploaded object key=6b71pfa7v9ha7vr5ikbfrld4jjqqklkn.narinfo error="server returned 404: 404 page not found\n"13562026/10/10 19:02:14 INFO Completed push id=1 objects=3 duration=32.051791ms13572026/10/10 19:02:14 INFO Upload complete. (208ms)13582026/10/10 19:02:14 INFO Received uploads request method=POST path=/api/pending_closures13592026/10/10 19:02:14 INFO Received push request method=POST path=/api/pushes13602026/10/10 19:02:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13612026/10/10 19:02:14 INFO Uploading n765cwmnn2g5hi38bsgczarsfxm179y0-unpinned-file.txt (128B)13622026/10/10 19:02:14 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"13632026/10/10 19:02:14 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13642026/10/10 19:02:14 WARN Failed to register uploaded object key=n765cwmnn2g5hi38bsgczarsfxm179y0.ls error="server returned 404: 404 page not found\n"13652026/10/10 19:02:14 INFO Signed narinfos id=2 count=113662026/10/10 19:02:14 INFO Uploading 1 narinfos13672026/10/10 19:02:14 INFO Received complete push request method=POST path=/api/pushes/2/complete13682026/10/10 19:02:14 WARN Failed to register uploaded object key=n765cwmnn2g5hi38bsgczarsfxm179y0.narinfo error="server returned 404: 404 page not found\n"13692026/10/10 19:02:14 INFO Completed push id=2 objects=3 duration=909.375µs13702026/10/10 19:02:14 INFO Upload complete. (172ms)13712026/10/10 19:02:14 INFO Starting cleanup of old closures method=DELETE path=/api/closures13722026/10/10 19:02:14 INFO Garbage collection started13732026/10/10 19:02:14 INFO Aborted multipart uploads count=0 kept=013742026/10/10 19:02:14 WARN Force mode enabled - objects will be deleted immediately without grace period13752026/10/10 19:02: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=013762026/10/10 19:02:15 INFO Vacuumed table table=pending_closures13772026/10/10 19:02:15 INFO Vacuumed table table=pending_objects13782026/10/10 19:02:15 INFO Vacuumed table table=multipart_uploads13792026/10/10 19:02:15 INFO Vacuumed table table=closures13802026/10/10 19:02:15 INFO Vacuumed table table=objects1381=== NAME TestOrphanedObjectsGCStressTest1382 orphaned_objects_gc_test.go:503: Stress test completed successfully:1383 orphaned_objects_gc_test.go:504: - Active objects preserved: 201384 orphaned_objects_gc_test.go:505: - Objects deleted: 2101385 orphaned_objects_gc_test.go:506: - Total GC'd: 2101386--- PASS: TestOrphanedObjectsGCStressTest (18.98s)1387=== CONT TestCacheStatsHandler13882026/10/10 19:02:15 INFO Received uploads request method=POST path=/api/pending_closures13892026/10/10 19:02:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13902026/10/10 19:02:16 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZjU1NDkzN2EtYjg3Mi00MTJhLTg3ZDQtZGU1YmI4YmE3MmVhLjYzYWU3NzBhLTg5ZmQtNGIzYi05MWQwLTJkODcyMGNlYWE0MHgxNzkxNjU4OTM2MDM2ODY2MDAw13912026/10/10 19:02:16 INFO Received uploads request method=POST path=/api/pending_closures13922026/10/10 19:02:16 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZjU1NDkzN2EtYjg3Mi00MTJhLTg3ZDQtZGU1YmI4YmE3MmVhLjYzYWU3NzBhLTg5ZmQtNGIzYi05MWQwLTJkODcyMGNlYWE0MHgxNzkxNjU4OTM2MDM2ODY2MDAw parts=11393--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (6.96s)1394=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13952026/10/10 19:02:16 INFO Received uploads request method=POST path=/api/pending_closures13962026/10/10 19:02:16 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13972026/10/10 19:02:16 INFO Uploading 9knbbp9mfrkcnv1v91by4bjfdpnabk4g-shared-dep (136B)13982026/10/10 19:02:16 INFO Uploading sfbipsmc7ck2lm3mbwhc5csrrx78xcqq-b (256B)13992026/10/10 19:02:16 WARN Failed to register uploaded object key=ds7ahh7381l2iyran874lxnjfar17m1f.ls error="server returned 404: 404 page not found\n"14002026/10/10 19:02:16 WARN Failed to register uploaded object key=sfbipsmc7ck2lm3mbwhc5csrrx78xcqq.ls error="server returned 404: 404 page not found\n"14012026/10/10 19:02:16 WARN Failed to register uploaded object key=nar/1zxbz2pp7s4wjwlvi7c6isiqr7lsjw03s03kykanzddywfr1ddyl.nar.zst error="server returned 404: 404 page not found\n"14022026/10/10 19:02:16 WARN Failed to register uploaded object key=9knbbp9mfrkcnv1v91by4bjfdpnabk4g.ls error="server returned 404: 404 page not found\n"14032026/10/10 19:02:16 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14042026/10/10 19:02:16 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14052026/10/10 19:02:16 INFO Signed narinfos id=1 count=214062026/10/10 19:02:16 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14072026/10/10 19:02:16 INFO Signed narinfos id=2 count=214082026/10/10 19:02:16 INFO Uploading 4 narinfos14092026/10/10 19:02:16 WARN Failed to register uploaded object key=9knbbp9mfrkcnv1v91by4bjfdpnabk4g.narinfo error="server returned 404: 404 page not found\n"14102026/10/10 19:02:16 WARN Failed to register uploaded object key=sfbipsmc7ck2lm3mbwhc5csrrx78xcqq.narinfo error="server returned 404: 404 page not found\n"14112026/10/10 19:02:16 WARN Failed to register uploaded object key=ds7ahh7381l2iyran874lxnjfar17m1f.narinfo error="server returned 404: 404 page not found\n"14122026/10/10 19:02:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14132026/10/10 19:02:16 WARN Failed to register uploaded object key=9knbbp9mfrkcnv1v91by4bjfdpnabk4g.narinfo error="server returned 404: 404 page not found\n"14142026/10/10 19:02:16 INFO Completed upload id=1 objects=6 duration=49.309125ms14152026/10/10 19:02:16 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14162026/10/10 19:02:16 INFO Completed upload id=2 objects=6 duration=470.542µs14172026/10/10 19:02:16 INFO Upload complete. (380ms)1418=== NAME TestClientFallsBackToClosures1419 client_pushes_test.go:112: Retrieved narinfo from S3:1420 StorePath: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientFallsBackToClosures2250523700/001/store/9knbbp9mfrkcnv1v91by4bjfdpnabk4g-shared-dep1421 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1422 Compression: zstd1423 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821424 NarSize: 1361425 References: 1426 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1427 client_pushes_test.go:112: Retrieved narinfo from S3:1428 StorePath: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientFallsBackToClosures2250523700/001/store/ds7ahh7381l2iyran874lxnjfar17m1f-a1429 URL: nar/1zxbz2pp7s4wjwlvi7c6isiqr7lsjw03s03kykanzddywfr1ddyl.nar.zst1430 Compression: zstd1431 NarHash: sha256:1zxbz2pp7s4wjwlvi7c6isiqr7lsjw03s03kykanzddywfr1ddyl1432 NarSize: 2561433 References: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientFallsBackToClosures2250523700/001/store/9knbbp9mfrkcnv1v91by4bjfdpnabk4g-shared-dep1434 CA: text:sha256:1dwdx4azl9fxv05z3752fa32lm625w77hswfrs0zf53hqydcy77j1435 client_pushes_test.go:112: Retrieved narinfo from S3:1436 StorePath: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientFallsBackToClosures2250523700/001/store/sfbipsmc7ck2lm3mbwhc5csrrx78xcqq-b1437 URL: nar/1zxbz2pp7s4wjwlvi7c6isiqr7lsjw03s03kykanzddywfr1ddyl.nar.zst1438 Compression: zstd1439 NarHash: sha256:1zxbz2pp7s4wjwlvi7c6isiqr7lsjw03s03kykanzddywfr1ddyl1440 NarSize: 2561441 References: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientFallsBackToClosures2250523700/001/store/9knbbp9mfrkcnv1v91by4bjfdpnabk4g-shared-dep1442 CA: text:sha256:1dwdx4azl9fxv05z3752fa32lm625w77hswfrs0zf53hqydcy77j1443--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (7.96s)1444=== CONT TestCacheConfigHandler1445=== RUN TestCacheConfigHandler/full_config,_no_issuer1446=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1447=== RUN TestCacheConfigHandler/no_cache_url_configured1448=== PAUSE TestCacheConfigHandler/no_cache_url_configured1449=== RUN TestCacheConfigHandler/no_signing_keys1450=== PAUSE TestCacheConfigHandler/no_signing_keys1451=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1452=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1453=== CONT TestService_AuthMiddleware_MTLSProxyHeader14542026/10/10 19:02:16 INFO Received uploads request method=POST path=/api/pending_closures1455--- PASS: TestClientFallsBackToClosures (7.92s)1456=== CONT TestService_ReadAuthMiddleware14572026/10/10 19:02:16 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=014582026/10/10 19:02:16 INFO Received create pin request method=POST path=/api/pins/myapp14592026/10/10 19:02:16 INFO Received uploads request method=POST path=/api/pending_closures14602026/10/10 19:02:16 INFO Created/updated pin name=myapp store_path=/private/var/tb/7/scratch/0e971e34819014b9/build/TestPinProtectsFromGC2270514905/001/store/6b71pfa7v9ha7vr5ikbfrld4jjqqklkn-pinned-file.txt narinfo_key=6b71pfa7v9ha7vr5ikbfrld4jjqqklkn.narinfo14612026/10/10 19:02:16 INFO Starting cleanup of old closures method=DELETE path=/api/closures14622026/10/10 19:02:16 INFO Garbage collection started14632026/10/10 19:02:16 INFO Aborted multipart uploads count=0 kept=014642026/10/10 19:02:16 WARN Force mode enabled - objects will be deleted immediately without grace period14652026/10/10 19:02: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=014662026/10/10 19:02:16 INFO Vacuumed table table=pending_closures14672026/10/10 19:02:16 INFO Vacuumed table table=pending_objects14682026/10/10 19:02:16 INFO Vacuumed table table=multipart_uploads14692026/10/10 19:02:16 INFO Vacuumed table table=closures14702026/10/10 19:02:16 INFO Vacuumed table table=objects14712026/10/10 19:02:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14722026/10/10 19:02:17 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZjU1NDkzN2EtYjg3Mi00MTJhLTg3ZDQtZGU1YmI4YmE3MmVhLjViNzZlY2IyLTQxNjItNGJlMy04ZDU5LWY3MTZhMjgxZTYxNngxNzkxNjU4OTM0NzQ0MzY1MDAw parts=1214732026/10/10 19:02:17 INFO Received uploads request method=POST path=/api/pending_closures1474--- PASS: TestCompletedNarNotReofferedAcrossClosures (8.73s)1475=== CONT TestService_ReadScope_PublicByDefault14762026/10/10 19:02:17 INFO Received push request method=POST path=/api/pushes14772026/10/10 19:02:17 INFO Received push request method=POST path=/api/pushes14782026/10/10 19:02:17 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14792026/10/10 19:02:17 INFO Uploading m57fy7k19v726bs3pwccqg61zqyyp6vp-shared-dep (136B)14802026/10/10 19:02:17 INFO Uploading pzc0yb4293c3nig5gs8krlcyjm78yswp-a (256B)1481--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (7.06s)1482=== CONT TestService_RequireScope_OIDC14832026/10/10 19:02:17 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14842026/10/10 19:02:17 WARN Failed to register uploaded object key=pzc0yb4293c3nig5gs8krlcyjm78yswp.ls error="server returned 404: 404 page not found\n"14852026/10/10 19:02:17 WARN Failed to register uploaded object key=m57fy7k19v726bs3pwccqg61zqyyp6vp.ls error="server returned 404: 404 page not found\n"14862026/10/10 19:02:17 WARN Failed to register uploaded object key=avcj6vm6ky7wrrba56kg1pvawkmd0afn.ls error="server returned 404: 404 page not found\n"14872026/10/10 19:02:17 WARN Failed to register uploaded object key=nar/0ink1nkwgzr9gx69a4bw9a2kk4r29lsmy134mf3rzpdfdcf1qybm.nar.zst error="server returned 404: 404 page not found\n"14882026/10/10 19:02:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14892026/10/10 19:02:17 INFO Signed narinfos id=1 count=314902026/10/10 19:02:17 INFO Uploading 3 narinfos14912026/10/10 19:02:17 WARN Failed to register uploaded object key=pzc0yb4293c3nig5gs8krlcyjm78yswp.narinfo error="server returned 404: 404 page not found\n"14922026/10/10 19:02:17 WARN Failed to register uploaded object key=avcj6vm6ky7wrrba56kg1pvawkmd0afn.narinfo error="server returned 404: 404 page not found\n"14932026/10/10 19:02:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63830/oidc14942026/10/10 19:02:17 INFO Received complete push request method=POST path=/api/pushes/1/complete14952026/10/10 19:02:17 WARN Failed to register uploaded object key=m57fy7k19v726bs3pwccqg61zqyyp6vp.narinfo error="server returned 404: 404 page not found\n"14962026/10/10 19:02:17 INFO Completed push id=1 objects=8 duration=89.718292ms14972026/10/10 19:02:17 INFO Upload complete. (360ms)1498=== NAME TestClientPushesUseOnePush1499 client_pushes_test.go:97: Retrieved narinfo from S3:1500 StorePath: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientPushesUseOnePush1121281266/001/store/m57fy7k19v726bs3pwccqg61zqyyp6vp-shared-dep1501 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1502 Compression: zstd1503 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821504 NarSize: 1361505 References: 1506 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1507 client_pushes_test.go:97: Retrieved narinfo from S3:1508 StorePath: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientPushesUseOnePush1121281266/001/store/pzc0yb4293c3nig5gs8krlcyjm78yswp-a1509 URL: nar/0ink1nkwgzr9gx69a4bw9a2kk4r29lsmy134mf3rzpdfdcf1qybm.nar.zst1510 Compression: zstd1511 NarHash: sha256:0ink1nkwgzr9gx69a4bw9a2kk4r29lsmy134mf3rzpdfdcf1qybm1512 NarSize: 2561513 References: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientPushesUseOnePush1121281266/001/store/m57fy7k19v726bs3pwccqg61zqyyp6vp-shared-dep1514 CA: text:sha256:163f3pyr426i4nlc8zzm3j7zdas7v4fj4lb6amlykjhldapqxgf71515 client_pushes_test.go:97: Retrieved narinfo from S3:1516 StorePath: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientPushesUseOnePush1121281266/001/store/avcj6vm6ky7wrrba56kg1pvawkmd0afn-b1517 URL: nar/0ink1nkwgzr9gx69a4bw9a2kk4r29lsmy134mf3rzpdfdcf1qybm.nar.zst1518 Compression: zstd1519 NarHash: sha256:0ink1nkwgzr9gx69a4bw9a2kk4r29lsmy134mf3rzpdfdcf1qybm1520 NarSize: 2561521 References: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientPushesUseOnePush1121281266/001/store/m57fy7k19v726bs3pwccqg61zqyyp6vp-shared-dep1522 CA: text:sha256:163f3pyr426i4nlc8zzm3j7zdas7v4fj4lb6amlykjhldapqxgf715232026/10/10 19:02:17 INFO Received push request method=POST path=/api/pushes1524--- PASS: TestClientPushesUseOnePush (7.91s)1525=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit15262026/10/10 19:02:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15272026/10/10 19:02:17 INFO Signed narinfos id=1 count=115282026/10/10 19:02:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15292026/10/10 19:02:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15302026/10/10 19:02:17 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"15312026/10/10 19:02:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15322026/10/10 19:02:17 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"15332026/10/10 19:02:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15342026/10/10 19:02:17 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=115352026/10/10 19:02:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15362026/10/10 19:02:17 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1537--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (6.57s)1538=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15392026/10/10 19:02:17 INFO Received uploads request method=POST path=/1540=== CONT TestParseSingleRange/none1541=== CONT TestPendingClosureWriteTimeout/empty1542=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15432026/10/10 19:02:17 INFO Received request for more parts method=POST path=/1544=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15452026/10/10 19:02:17 INFO Received complete multipart upload request method=POST path=/1546=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15472026/10/10 19:02:17 INFO Received uploads request method=POST path=/1548--- PASS: TestUploadHandlersRejectInvalidKeys (0.05s)1549 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1550 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.01s)1551 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1552 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1553=== CONT TestIsValidCachePath/narinfo1554=== CONT TestProxyWriteTimeout/narinfo1555=== CONT TestIsValidCachePath/short_hash1556=== CONT TestIsValidCachePath/wrong_extension1557=== CONT TestIsValidCachePath/leading_slash1558=== CONT TestIsValidCachePath/empty1559=== CONT TestIsValidCachePath/random_path1560=== CONT TestIsValidCachePath/invalid_char_u1561=== CONT TestIsValidCachePath/invalid_char_e1562=== CONT TestIsValidCachePath/traversal_in_middle1563=== CONT TestIsValidCachePath/traversal_parent1564=== CONT TestIsValidCachePath/index.html1565=== CONT TestIsValidCachePath/nix-cache-info1566=== CONT TestIsValidCachePath/realisation1567=== CONT TestIsValidCachePath/log1568=== CONT TestIsValidCachePath/ls1569=== CONT TestIsValidCachePath/nar_uncompressed1570=== CONT TestIsValidCachePath/nar_bz21571=== CONT TestIsValidCachePath/nar_xz1572=== CONT TestIsValidCachePath/nar_zst1573=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1574--- PASS: TestIsValidCachePath (0.05s)1575 --- PASS: TestIsValidCachePath/narinfo (0.00s)1576 --- PASS: TestIsValidCachePath/short_hash (0.00s)1577 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1578 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1579 --- PASS: TestIsValidCachePath/empty (0.00s)1580 --- PASS: TestIsValidCachePath/random_path (0.00s)1581 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1582 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1583 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1584 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1585 --- PASS: TestIsValidCachePath/index.html (0.00s)1586 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1587 --- PASS: TestIsValidCachePath/realisation (0.00s)1588 --- PASS: TestIsValidCachePath/log (0.00s)1589 --- PASS: TestIsValidCachePath/ls (0.00s)1590 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1591 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1592 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1593 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1594 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1595=== CONT TestProxyWriteTimeout/unknown_size1596=== CONT TestProxyWriteTimeout/10_GiB_nar1597=== CONT TestProxyWriteTimeout/1_GiB_nar1598--- PASS: TestProxyWriteTimeout (0.00s)1599 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1600 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1601 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1602 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1603=== CONT TestParseSingleRange/malformed_end_before_start1604=== CONT TestParseSingleRange/start_far_past_EOF1605=== CONT TestParseSingleRange/start_past_EOF1606=== CONT TestParseSingleRange/single_byte1607=== CONT TestParseSingleRange/suffix_exceeds_size1608=== CONT TestParseSingleRange/suffix1609=== CONT TestParseSingleRange/end_clamped_to_size1610=== CONT TestParseSingleRange/open-ended1611=== CONT TestParseSingleRange/closed1612=== CONT TestParseSingleRange/malformed_no_dash1613=== CONT TestParseSingleRange/malformed_both_empty1614=== CONT TestParseSingleRange/multi-range_ignored1615=== CONT TestPendingClosureWriteTimeout/670k_objects1616=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline16172026/10/10 19:02:18 INFO Received push request method=POST path=/api/pushes16182026/10/10 19:02:18 INFO Received push request method=POST path=/api/pushes16192026/10/10 19:02:18 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16202026/10/10 19:02:18 INFO Uploading gla3mg483kzab7kkqx0bp6p8hg0i6xgd-shared-dep (136B)16212026/10/10 19:02:18 INFO Uploading nz0nv87ixg9xaalp1cwarpjx8mj2xpfd-top (264B)16222026/10/10 19:02:18 WARN Failed to register uploaded object key=nz0nv87ixg9xaalp1cwarpjx8mj2xpfd.ls error="server returned 404: 404 page not found\n"16232026/10/10 19:02:18 WARN Failed to register uploaded object key=nar/0p9abax17xdki2i6005fjp0pmrn6fa4xwywz8gkp5fq4hr03w38f.nar.zst error="server returned 404: 404 page not found\n"16242026/10/10 19:02:18 WARN Failed to register uploaded object key=gla3mg483kzab7kkqx0bp6p8hg0i6xgd.ls error="server returned 404: 404 page not found\n"16252026/10/10 19:02:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16262026/10/10 19:02:18 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16272026/10/10 19:02:18 INFO Signed narinfos id=1 count=216282026/10/10 19:02:18 INFO Uploading 2 narinfos16292026/10/10 19:02:18 WARN Failed to register uploaded object key=nz0nv87ixg9xaalp1cwarpjx8mj2xpfd.narinfo error="server returned 404: 404 page not found\n"16302026/10/10 19:02:18 INFO Received complete push request method=POST path=/api/pushes/1/complete16312026/10/10 19:02:18 WARN Failed to register uploaded object key=gla3mg483kzab7kkqx0bp6p8hg0i6xgd.narinfo error="server returned 404: 404 page not found\n"16322026/10/10 19:02:18 INFO Completed push id=1 objects=6 duration=26.302875ms16332026/10/10 19:02:18 INFO Upload complete. (200ms)1634=== NAME TestClientSharedPathCommittedMidPush1635 client_integration_test.go:680: Retrieved narinfo from S3:1636 StorePath: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientSharedPathCommittedMidPush3773879691/001/store/gla3mg483kzab7kkqx0bp6p8hg0i6xgd-shared-dep1637 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1638 Compression: zstd1639 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821640 NarSize: 1361641 References: 1642 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1643 client_integration_test.go:680: Retrieved narinfo from S3:1644 StorePath: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientSharedPathCommittedMidPush3773879691/001/store/nz0nv87ixg9xaalp1cwarpjx8mj2xpfd-top1645 URL: nar/0p9abax17xdki2i6005fjp0pmrn6fa4xwywz8gkp5fq4hr03w38f.nar.zst1646 Compression: zstd1647 NarHash: sha256:0p9abax17xdki2i6005fjp0pmrn6fa4xwywz8gkp5fq4hr03w38f1648 NarSize: 2641649 References: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientSharedPathCommittedMidPush3773879691/001/store/gla3mg483kzab7kkqx0bp6p8hg0i6xgd-shared-dep1650 CA: text:sha256:064276p55wdkhl2mijh4vcc8yqqixkfhn08pa0g8w440vb0n31fw1651=== RUN TestPush_RejectsBadRequests/bad_root1652=== PAUSE TestPush_RejectsBadRequests/bad_root1653=== RUN TestPush_RejectsBadRequests/root_not_in_objects1654=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1655=== RUN TestPush_RejectsBadRequests/no_roots1656=== PAUSE TestPush_RejectsBadRequests/no_roots1657=== RUN TestPush_RejectsBadRequests/no_objects1658=== PAUSE TestPush_RejectsBadRequests/no_objects1659=== CONT TestParseSingleRange/unknown_unit1660=== CONT TestPendingClosureWriteTimeout/400_objects1661=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1662--- PASS: TestParseSingleRange (0.05s)1663 --- PASS: TestParseSingleRange/none (0.00s)1664 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1665 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1666 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1667 --- PASS: TestParseSingleRange/single_byte (0.00s)1668 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1669 --- PASS: TestParseSingleRange/suffix (0.00s)1670 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1671 --- PASS: TestParseSingleRange/open-ended (0.00s)1672 --- PASS: TestParseSingleRange/closed (0.00s)1673 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1674 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1675 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1676 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1677=== NAME TestPinProtectsFromGC1678 client_integration_test.go:840: Pin successfully protected closure from garbage collection1679--- PASS: TestClientSharedPathCommittedMidPush (7.44s)1680=== CONT TestIsValidUploadKey/narinfo1681=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh16822026-10-10 19:02:18.998 UTC [98247] ERROR: Push does not exist: id=116832026-10-10 19:02:18.998 UTC [98247] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE16842026-10-10 19:02:18.998 UTC [98247] STATEMENT: SELECT commit_push($1)1685--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (6.97s)1686=== CONT TestIsValidUploadKey/unknown_type1687=== CONT TestIsValidUploadKey/empty_key1688=== CONT TestIsValidUploadKey/absolute1689=== CONT TestIsValidUploadKey/traversal_nar1690=== CONT TestIsValidUploadKey/traversal1691=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1692=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1693=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1694=== CONT TestIsValidUploadKey/index.html1695=== CONT TestIsValidUploadKey/nix-cache-info1696=== CONT TestIsValidUploadKey/realisation_plus_in_output1697=== CONT TestIsValidUploadKey/realisation1698=== CONT TestIsValidUploadKey/build_log_equals1699=== CONT TestIsValidUploadKey/build_log_question_mark1700=== CONT TestIsValidUploadKey/build_log_plus_in_name1701=== CONT TestIsValidUploadKey/build_log_home-manager_file1702=== CONT TestIsValidUploadKey/build_log1703=== CONT TestIsValidUploadKey/listing1704=== CONT TestIsValidUploadKey/nar_plain1705=== CONT TestIsValidUploadKey/nar_xz1706=== CONT TestIsValidUploadKey/nar_zst1707--- PASS: TestIsValidUploadKey (0.05s)1708 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1709 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1710 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1711 --- PASS: TestIsValidUploadKey/absolute (0.00s)1712 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1713 --- PASS: TestIsValidUploadKey/traversal (0.00s)1714 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1715 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1716 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1717 --- PASS: TestIsValidUploadKey/index.html (0.00s)1718 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1719 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1720 --- PASS: TestIsValidUploadKey/realisation (0.00s)1721 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1722 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1723 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1724 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1725 --- PASS: TestIsValidUploadKey/build_log (0.00s)1726 --- PASS: TestIsValidUploadKey/listing (0.00s)1727 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1728 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1729 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1730=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17312026/10/10 19:02:19 INFO Received request for more parts method=POST path=/1732--- PASS: TestPinProtectsFromGC (11.35s)1733=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17342026/10/10 19:02:19 INFO Received complete multipart upload request method=POST path=/1735=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17362026/10/10 19:02:19 INFO Received uploads request method=POST path=/1737=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17382026/10/10 19:02:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17392026/10/10 19:02:19 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZjU1NDkzN2EtYjg3Mi00MTJhLTg3ZDQtZGU1YmI4YmE3MmVhLjQxMjA4OTQzLTQ2YTUtNGQ4NS05ZjE0LTI4MjViNGUxYjUwNngxNzkxNjU4OTM2ODU5MDA3MDAw parts=1217402026/10/10 19:02:19 INFO Received uploads request method=POST path=/api/pending_closures17412026/10/10 19:02:19 INFO Received uploads request method=POST path=/api/pending_closures1742--- PASS: TestUploadHandlersRejectOversizedBody (0.08s)1743 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)1744 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1745 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)1746=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check17472026/10/10 19:02:19 INFO Received push request method=POST path=/api/pushes17482026/10/10 19:02:19 INFO Received complete push request method=POST path=/api/pushes/1/complete17492026/10/10 19:02:19 INFO Completed push id=1 objects=4 duration=48.140375ms1750--- PASS: TestPush_RepeatedRootCommitsOnce (7.32s)1751=== CONT TestServerTLSConfig/no_client_CA1752=== CONT TestServerTLSConfig/not_a_PEM_file1753=== NAME TestClientWithDependencies1754 client_integration_test.go:613: Built derivation: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientWithDependencies3875037753/001/store/cyb2zh5hx90sx7q8qbxddv8vv8jcyrcz-test-script1755=== CONT TestServerTLSConfig/missing_CA_file1756=== CONT TestGCEndsOnShutdown/before_the_run1757--- PASS: TestServerTLSConfig (0.00s)1758 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1759 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1760 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1761=== NAME TestClientWithDependencies1762 client_integration_test.go:615: Found 1 dependencies (including self)17632026/10/10 19:02:20 INFO Received push request method=POST path=/api/pushes17642026/10/10 19:02:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17652026/10/10 19:02:20 INFO Uploading cyb2zh5hx90sx7q8qbxddv8vv8jcyrcz-test-script (136B)17662026/10/10 19:02:20 WARN Failed to register uploaded object key=cyb2zh5hx90sx7q8qbxddv8vv8jcyrcz.ls error="server returned 404: 404 page not found\n"17672026/10/10 19:02:20 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17682026/10/10 19:02:20 WARN Failed to register uploaded object key=log/3r170ipsigin6kz69iffrl5sbdikjjad-test-script.drv error="server returned 404: 404 page not found\n"17692026/10/10 19:02:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17702026/10/10 19:02:20 INFO Signed narinfos id=1 count=117712026/10/10 19:02:20 INFO Uploading 1 narinfos17722026/10/10 19:02:20 INFO Received complete push request method=POST path=/api/pushes/1/complete17732026/10/10 19:02:20 WARN Failed to register uploaded object key=cyb2zh5hx90sx7q8qbxddv8vv8jcyrcz.narinfo error="server returned 404: 404 page not found\n"17742026/10/10 19:02:20 INFO Completed push id=1 objects=4 duration=24.940917ms17752026/10/10 19:02:20 INFO Upload complete. (311ms)1776 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/7/scratch/0e971e34819014b9/build/TestClientWithDependencies3875037753/001/store) requires matching store prefix1777--- PASS: TestClientWithDependencies (8.05s)1778=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17792026/10/10 19:02:20 INFO Received push request method=POST path=/api/pushes17802026/10/10 19:02:20 INFO Received complete push request method=POST path=/api/pushes/1/complete17812026/10/10 19:02:20 INFO Completed push id=1 objects=6 duration=38.747458ms1782--- PASS: TestPush_CompleteCommitsEveryRoot (7.72s)1783=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1784--- PASS: TestDeleteClosuresRacingPins (12.80s)1785=== CONT TestResolveDBConnectionString/flag_wins1786=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1787=== CONT TestResolveDBConnectionString/nothing_configured1788=== CONT TestResolveDBConnectionString/missing_file_is_an_error1789=== CONT TestResolveDBConnectionString/file_when_flag_empty1790=== CONT TestClientErrorHandling/InvalidStorePath1791--- PASS: TestResolveDBConnectionString (0.02s)1792 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1793 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1794 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1795 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1796 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1797=== NAME TestClientCADerivations1798 client_ca_test.go:136: Built CA derivation: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientCADerivations2228454302/001/store/n2i284dmj85prgryfjxibbc46vj1wcgr-ca-test1799 client_ca_test.go:139: Found 1 dependencies (including self)18002026/10/10 19:02:21 INFO Received push request method=POST path=/api/pushes18012026/10/10 19:02:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18022026/10/10 19:02:21 INFO Uploading n2i284dmj85prgryfjxibbc46vj1wcgr-ca-test (144B)18032026/10/10 19:02:21 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18042026/10/10 19:02:21 WARN Failed to register uploaded object key=n2i284dmj85prgryfjxibbc46vj1wcgr.ls error="server returned 404: 404 page not found\n"18052026/10/10 19:02:21 WARN Failed to register uploaded object key=log/c4d0b4xcrbjpvg0sr07ivry65amlppr7-ca-test.drv error="server returned 404: 404 page not found\n"18062026/10/10 19:02:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18072026/10/10 19:02:21 INFO Signed narinfos id=1 count=118082026/10/10 19:02:21 INFO Uploading 1 narinfos1809=== NAME TestClientMultipleUploads1810 client_integration_test.go:358: Created store path 0: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientMultipleUploads3450341109/001/store/ricp6yr8hvv8p9qs1qpqvzzh8rs9v2hc-test-file-0.txt18112026/10/10 19:02:21 INFO Received complete push request method=POST path=/api/pushes/1/complete18122026/10/10 19:02:21 WARN Failed to register uploaded object key=n2i284dmj85prgryfjxibbc46vj1wcgr.narinfo error="server returned 404: 404 page not found\n"18132026/10/10 19:02:21 INFO Completed push id=1 objects=4 duration=32.168ms18142026/10/10 19:02:21 INFO Upload complete. (412ms)1815=== NAME TestClientCADerivations1816 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientCADerivations2228454302/001/store/n2i284dmj85prgryfjxibbc46vj1wcgr-ca-test1817 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1818 Compression: zstd1819 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1820 NarSize: 1441821 References: 1822 Deriver: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientCADerivations2228454302/001/store/c4d0b4xcrbjpvg0sr07ivry65amlppr7-ca-test.drv1823 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1824 client_ca_test.go:185: Checking for realisation files in S3...1825 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1826 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1827=== NAME TestClientMultipleUploads1828 client_integration_test.go:358: Created store path 1: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientMultipleUploads3450341109/001/store/fhmw1h05z1i4m7xz2xa0a9s31gi7x5cv-test-file-1.txt18292026/10/10 19:02:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1830=== NAME TestClientCADerivations1831 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket76?endpoint=http://localhost:63642®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/7/scratch/0e971e34819014b9/build/TestClientCADerivations2228454302/001/store'1832 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11833=== NAME TestClientMultipleUploads1834 client_integration_test.go:358: Created store path 2: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientMultipleUploads3450341109/001/store/h1svky1ps7y2v11pmvknariril7srj9x-test-file-2.txt18352026/10/10 19:02:21 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZjU1NDkzN2EtYjg3Mi00MTJhLTg3ZDQtZGU1YmI4YmE3MmVhLjVlNGM5OGYyLWNiMTYtNDQyZi1hN2Q4LTc4MGY0MzFmY2E3N3gxNzkxNjU4OTM5MjYxNzUyMDAw error="Get \"http://127.0.0.1:1/bucket68/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"18362026/10/10 19:02:21 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZjU1NDkzN2EtYjg3Mi00MTJhLTg3ZDQtZGU1YmI4YmE3MmVhLjhkNDQ3OTJiLWYwMTItNDk2NC04NGQ3LTZhM2NkZTYwNjZhYXgxNzkxNjU4OTM5MjA5NzYzMDAw parts=1218372026/10/10 19:02:21 INFO Received cleanup request method=DELETE path=/api/pending_closures18382026/10/10 19:02:21 INFO Aborted multipart uploads count=1 kept=01839=== NAME TestClientIntegration1840 client_integration_test.go:286: Created store path: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientIntegration4175278797/002/store/p59dg68dkavzasai4vajklfqn4k98qxn-test-file.txt1841--- PASS: TestRedundantMultipartUpload (11.77s)1842=== CONT TestClientErrorHandling/ServerNotAvailable18432026/10/10 19:02:21 INFO Received push request method=POST path=/api/pushes1844--- PASS: TestClientCADerivations (9.05s)1845=== CONT TestClientErrorHandling/InvalidAuthToken1846--- PASS: TestReadRedirectUsesPublicS3URL (7.94s)1847=== CONT TestCacheConfigHandler/full_config,_no_issuer1848=== CONT TestCacheConfigHandler/no_signing_keys1849=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1850=== CONT TestCacheConfigHandler/no_cache_url_configured1851--- PASS: TestCacheConfigHandler (0.01s)1852 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1853 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1854 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1855 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1856=== CONT TestPush_RejectsBadRequests/bad_root18572026/10/10 19:02:21 INFO Received push request method=POST path=/api/pushes1858=== CONT TestPush_RejectsBadRequests/no_roots18592026/10/10 19:02:21 INFO Received push request method=POST path=/api/pushes1860=== CONT TestPush_RejectsBadRequests/root_not_in_objects18612026/10/10 19:02:21 INFO Received push request method=POST path=/api/pushes1862=== CONT TestPush_RejectsBadRequests/no_objects18632026/10/10 19:02:21 INFO Received push request method=POST path=/api/pushes1864--- PASS: TestPush_RejectsBadRequests (6.49s)1865 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1866 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1867 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1868 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)18692026/10/10 19:02:21 INFO Received push request method=POST path=/api/pushes18702026/10/10 19:02:21 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18712026/10/10 19:02:21 INFO Uploading ricp6yr8hvv8p9qs1qpqvzzh8rs9v2hc-test-file-0.txt (160B)18722026/10/10 19:02:21 INFO Uploading fhmw1h05z1i4m7xz2xa0a9s31gi7x5cv-test-file-1.txt (160B)18732026/10/10 19:02:21 INFO Uploading h1svky1ps7y2v11pmvknariril7srj9x-test-file-2.txt (160B)18742026/10/10 19:02:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18752026/10/10 19:02:21 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18762026/10/10 19:02:21 INFO Uploading p59dg68dkavzasai4vajklfqn4k98qxn-test-file.txt (152B)18772026/10/10 19:02:21 WARN Failed to register uploaded object key=h1svky1ps7y2v11pmvknariril7srj9x.ls error="server returned 404: 404 page not found\n"18782026/10/10 19:02:21 WARN Failed to register uploaded object key=ricp6yr8hvv8p9qs1qpqvzzh8rs9v2hc.ls error="server returned 404: 404 page not found\n"18792026/10/10 19:02:21 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18802026/10/10 19:02:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18812026/10/10 19:02:21 WARN Failed to register uploaded object key=fhmw1h05z1i4m7xz2xa0a9s31gi7x5cv.ls error="server returned 404: 404 page not found\n"18822026/10/10 19:02:21 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18832026/10/10 19:02:21 INFO Signed narinfos id=1 count=318842026/10/10 19:02:21 INFO Uploading 3 narinfos18852026/10/10 19:02:21 WARN Failed to register uploaded object key=p59dg68dkavzasai4vajklfqn4k98qxn.ls error="server returned 404: 404 page not found\n"18862026/10/10 19:02:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18872026/10/10 19:02:21 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18882026/10/10 19:02:21 INFO Signed narinfos id=1 count=118892026/10/10 19:02:21 INFO Uploading 1 narinfos18902026/10/10 19:02:21 WARN Failed to register uploaded object key=h1svky1ps7y2v11pmvknariril7srj9x.narinfo error="server returned 404: 404 page not found\n"18912026/10/10 19:02:21 INFO Received complete push request method=POST path=/api/pushes/1/complete18922026/10/10 19:02:21 WARN Failed to register uploaded object key=ricp6yr8hvv8p9qs1qpqvzzh8rs9v2hc.narinfo error="server returned 404: 404 page not found\n"18932026/10/10 19:02:21 WARN Failed to register uploaded object key=fhmw1h05z1i4m7xz2xa0a9s31gi7x5cv.narinfo error="server returned 404: 404 page not found\n"18942026/10/10 19:02:22 INFO Received complete push request method=POST path=/api/pushes/1/complete18952026/10/10 19:02:22 WARN Failed to register uploaded object key=p59dg68dkavzasai4vajklfqn4k98qxn.narinfo error="server returned 404: 404 page not found\n"18962026/10/10 19:02:22 INFO Completed push id=1 objects=9 duration=42.47125ms18972026/10/10 19:02:22 INFO Upload complete. (336ms)1898=== NAME TestClientMultipleUploads1899 client_integration_test.go:369: Uploaded 3 paths in 390.691958ms19002026/10/10 19:02:22 INFO Completed push id=1 objects=3 duration=54.573084ms19012026/10/10 19:02:22 INFO Upload complete. (284ms)19022026/10/10 19:02:22 INFO All 1 paths already cached1903=== NAME TestClientIntegration1904 client_integration_test.go:312: Retrieved narinfo from S3:1905 StorePath: /private/var/tb/7/scratch/0e971e34819014b9/build/TestClientIntegration4175278797/002/store/p59dg68dkavzasai4vajklfqn4k98qxn-test-file.txt1906 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1907 Compression: zstd1908 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11909 NarSize: 1521910 References: 1911 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11912 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1913 client_integration_test.go:313: Decompressed .ls content (64 bytes):1914 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1915 client_integration_test.go:316: Testing garbage collection...1916--- PASS: TestClientMultipleUploads (9.18s)19172026/10/10 19:02:22 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19182026/10/10 19:02:22 INFO Starting cleanup of old closures method=DELETE path=/api/closures19192026/10/10 19:02:22 INFO Garbage collection started19202026/10/10 19:02:22 INFO Aborted multipart uploads count=0 kept=019212026/10/10 19:02:22 WARN Force mode enabled - objects will be deleted immediately without grace period1922--- PASS: TestReadProxyRangeRequest (8.42s)19232026/10/10 19:02:22 WARN Request failed, retrying attempt=2 backoff=203.888441ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19242026/10/10 19:02:22 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=019252026/10/10 19:02:22 INFO Vacuumed table table=pending_closures19262026/10/10 19:02:22 INFO Vacuumed table table=pending_objects19272026/10/10 19:02:22 INFO Vacuumed table table=multipart_uploads19282026/10/10 19:02:22 INFO Vacuumed table table=closures19292026/10/10 19:02:22 WARN Request failed, retrying attempt=3 backoff=398.623495ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19302026/10/10 19:02:22 INFO Vacuumed table table=objects1931--- PASS: TestReadRedirectKeepsNarinfoProxied (8.75s)19322026/10/10 19:02:22 WARN Request failed, retrying attempt=4 backoff=758.450833ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1933=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1934=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1935=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1936=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1937=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1938=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1939=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1940=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1941=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1942=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1943=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected1944=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19452026/10/10 19:02:23 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]19462026/10/10 19:02:23 WARN Authentication failed token_preview=eyJhbGciOi...VnYwALPzww token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1947--- PASS: TestService_AuthMiddleware_OIDC (8.86s)1948 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1949 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)1950 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1951 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)19522026-10-10 19:02:23.324 UTC [97841] LOG: checkpoint starting: wal1953--- PASS: TestCacheStatsHandler (7.73s)19542026/10/10 19:02:23 WARN Request failed, retrying attempt=5 backoff=1.539083372s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1955--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (7.02s)19562026/10/10 19:02:24 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19572026/10/10 19:02:24 WARN mTLS auth: bound subjects configured but subject DN unavailable19582026/10/10 19:02:24 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1959--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (7.71s)19602026/10/10 19:02:24 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01961=== NAME TestClientIntegration1962 client_integration_test.go:323: Objects in database after GC:1963 client_integration_test.go:323: Successfully deleted all objects with GC --force1964--- PASS: TestClientIntegration (10.70s)1965--- PASS: TestService_ReadAuthMiddleware (7.61s)1966--- PASS: TestService_ReadScope_PublicByDefault (7.44s)19672026/10/10 19:02:24 INFO Received uploads request method=POST path=/api/pending_closures1968=== RUN TestService_RequireScope_OIDC/builder_may_write1969=== PAUSE TestService_RequireScope_OIDC/builder_may_write1970=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1971=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1972=== RUN TestService_RequireScope_OIDC/ops_may_admin1973=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1974=== RUN TestService_RequireScope_OIDC/ops_may_not_write1975=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1976=== RUN TestService_RequireScope_OIDC/reader_may_not_write1977=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1978=== RUN TestService_RequireScope_OIDC/static_token_may_admin1979=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1980=== RUN TestService_RequireScope_OIDC/static_token_may_write1981=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1982=== RUN TestService_RequireScope_OIDC/reader_may_read1983=== PAUSE TestService_RequireScope_OIDC/reader_may_read1984=== RUN TestService_RequireScope_OIDC/writer_implies_read1985=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1986=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1987=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1988=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1989=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1990=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1991=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1992=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1993=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1994=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1995=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1996=== CONT TestService_RequireScope_OIDC/builder_may_write1997=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1998=== CONT TestService_RequireScope_OIDC/static_token_may_admin1999=== CONT TestService_RequireScope_OIDC/reader_may_read2000=== CONT TestService_RequireScope_OIDC/writer_implies_read2001=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20022026/10/10 19:02:25 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]2003=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2004=== CONT TestService_RequireScope_OIDC/static_token_may_write2005=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2006=== CONT TestService_RequireScope_OIDC/ops_may_not_write2007=== CONT TestService_RequireScope_OIDC/reader_may_not_write2008=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2009=== CONT TestService_RequireScope_OIDC/ops_may_admin2010=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2011--- PASS: TestService_RequireScope_OIDC (7.57s)2012 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2013 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2014 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2015 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2016 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2017 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2018 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2019 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2020 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2021 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2022 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2023 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2024 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2025 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)20262026/10/10 19:02:25 INFO Received push request method=POST path=/api/pushes20272026/10/10 19:02:25 INFO Received complete push request method=POST path=/api/pushes/1/complete20282026/10/10 19:02:25 INFO Completed push id=1 objects=4 duration=12.429ms20292026/10/10 19:02:25 INFO Received push request method=POST path=/api/pushes20302026/10/10 19:02:25 INFO Aborted multipart uploads count=0 kept=020312026/10/10 19:02:25 WARN Force mode enabled - objects will be deleted immediately without grace period20322026/10/10 19:02:25 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=020332026/10/10 19:02:25 INFO Vacuumed table table=pending_closures20342026/10/10 19:02:25 INFO Vacuumed table table=pending_objects20352026/10/10 19:02:25 INFO Vacuumed table table=multipart_uploads20362026/10/10 19:02:25 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20372026/10/10 19:02:25 INFO Vacuumed table table=closures20382026/10/10 19:02:25 INFO Vacuumed table table=objects20392026/10/10 19:02:25 INFO Received complete push request method=POST path=/api/pushes/2/complete20402026/10/10 19:02:25 INFO Completed push id=2 objects=4 duration=1.409584ms2041--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (7.51s)20422026/10/10 19:02:25 INFO Received uploads request method=POST path=/api/pending_closures20432026/10/10 19:02:25 WARN Request failed, retrying attempt=2 backoff=181.573156ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20442026/10/10 19:02:25 INFO Aborted multipart uploads count=0 kept=020452026/10/10 19:02:25 WARN Force mode enabled - objects will be deleted immediately without grace period20462026/10/10 19:02: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=020472026/10/10 19:02:25 INFO Vacuumed table table=pending_closures20482026/10/10 19:02:25 INFO Vacuumed table table=pending_objects20492026/10/10 19:02:25 INFO Vacuumed table table=multipart_uploads20502026/10/10 19:02:25 INFO Vacuumed table table=closures20512026/10/10 19:02:25 INFO Vacuumed table table=objects20522026/10/10 19:02:25 WARN Request failed, retrying attempt=3 backoff=385.627484ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2053--- PASS: TestPendingClosureWriteTimeout (0.00s)2054 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2055 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2056 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2057 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (7.78s)20582026/10/10 19:02:25 INFO Received uploads request method=POST path=/api/pending_closures20592026/10/10 19:02:25 INFO Aborted multipart uploads count=0 kept=020602026/10/10 19:02:25 WARN Force mode enabled - objects will be deleted immediately without grace period20612026/10/10 19:02: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=020622026/10/10 19:02:25 INFO Vacuumed table table=pending_closures20632026/10/10 19:02:25 INFO Vacuumed table table=pending_objects20642026/10/10 19:02:25 INFO Vacuumed table table=multipart_uploads20652026/10/10 19:02:25 INFO Vacuumed table table=closures20662026/10/10 19:02:25 INFO Vacuumed table table=objects2067--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2068 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (6.43s)2069 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (6.47s)20702026/10/10 19:02:25 WARN Request failed, retrying attempt=4 backoff=819.675957ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20712026/10/10 19:02:26 INFO Aborted multipart uploads count=0 kept=020722026/10/10 19:02:26 WARN Force mode enabled - objects will be deleted immediately without grace period20732026-10-10 19:02:26.071 UTC [98354] ERROR: canceling statement due to user request20742026-10-10 19:02:26.071 UTC [98354] STATEMENT: -- name: MarkStaleObjects :execrows2075 WITH RECURSIVE ct AS (2076 SELECT timezone('UTC', now()) AS now2077 ),2078 closure_reach AS (2079 -- Start with all closure keys2080 SELECT o.key, o.refs2081 FROM objects o2082 INNER JOIN closures c ON o.key = c.key2083 UNION2084 -- Recursively add all referenced objects2085 SELECT o.key, o.refs2086 FROM objects o2087 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2088 ),2089 reachable_objects AS (2090 SELECT DISTINCT key FROM closure_reach2091 ),2092 stale_objects AS (2093 SELECT o.key2094 FROM objects AS o, ct2095 WHERE2096 NOT EXISTS (2097 SELECT 12098 FROM reachable_objects ro2099 WHERE ro.key = o.key2100 )2101 AND NOT EXISTS (2102 SELECT 12103 FROM pending_objects AS po2104 WHERE po.key = o.key2105 )2106 AND o.deleted_at IS NULL -- Only mark fresh objects2107 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2108 FOR UPDATE2109 )2110 UPDATE objects2111 SET2112 deleted_at = ct.now,2113 first_deleted_at = COALESCE(first_deleted_at, ct.now)2114 FROM stale_objects, ct2115 WHERE objects.key = stale_objects.key2116 2117--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2118 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (6.85s)2119 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (7.09s)21202026/10/10 19:02:26 INFO Aborted multipart uploads count=0 kept=021212026/10/10 19:02:26 WARN Force mode enabled - objects will be deleted immediately without grace period21222026/10/10 19:02:26 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:63642/bucket98/?delete=\": context canceled"2123--- PASS: TestGCEndsOnShutdown (0.01s)2124 --- PASS: TestGCEndsOnShutdown/before_the_run (6.01s)2125 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (5.58s)2126 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (5.47s)21272026/10/10 19:02:26 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21282026/10/10 19:02:26 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21292026/10/10 19:02:26 WARN Request failed, retrying attempt=5 backoff=1.607999737s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21302026/10/10 19:02:28 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused"21312026/10/10 19:02:28 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21322026/10/10 19:02:28 WARN Request failed, retrying attempt=2 backoff=189.128581ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21332026/10/10 19:02:28 WARN Request failed, retrying attempt=3 backoff=372.579468ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21342026/10/10 19:02:29 WARN Request failed, retrying attempt=4 backoff=801.505384ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21352026/10/10 19:02:29 WARN Request failed, retrying attempt=5 backoff=1.711808063s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21362026/10/10 19:02:31 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21372026/10/10 19:02:31 WARN Request failed, retrying attempt=2 backoff=195.237367ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21382026/10/10 19:02:31 WARN Request failed, retrying attempt=3 backoff=433.030817ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21392026/10/10 19:02:32 WARN Request failed, retrying attempt=4 backoff=820.720666ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21402026/10/10 19:02:33 WARN Request failed, retrying attempt=5 backoff=1.684199547s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2141--- PASS: TestClientErrorHandling (0.00s)2142 --- PASS: TestClientErrorHandling/InvalidStorePath (5.58s)2143 --- PASS: TestClientErrorHandling/InvalidAuthToken (4.69s)2144 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.09s)2145PASS2146{"timestamp":"2026-10-10T19:02:34.871617Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:63690","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}21472026-10-10 19:02:35.008 UTC [97836] LOG: received smart shutdown request21482026-10-10 19:02:35.009 UTC [97836] LOG: background worker "logical replication launcher" (PID 97846) exited with exit code 121492026-10-10 19:02:36.168 UTC [97841] LOG: checkpoint complete: wrote 10195 buffers (62.2%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=12.060 s, sync=0.609 s, total=12.844 s; sync files=34044, longest=0.001 s, average=0.001 s; distance=532978 kB, estimate=532978 kB; lsn=0/228B48C8, redo lsn=0/2200981021502026-10-10 19:02:36.168 UTC [97841] LOG: shutting down21512026-10-10 19:02:36.168 UTC [97841] LOG: checkpoint starting: shutdown immediate21522026-10-10 19:02:36.221 UTC [97841] LOG: checkpoint complete: wrote 1246 buffers (7.6%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.042 s, sync=0.009 s, total=0.053 s; sync files=493, longest=0.001 s, average=0.001 s; distance=8876 kB, estimate=480567 kB; lsn=0/228B4940, redo lsn=0/228B494021532026-10-10 19:02:36.227 UTC [97836] LOG: database system is shut down2154Running OIDC tests...2155=== RUN TestAudienceForIssuer2156=== PAUSE TestAudienceForIssuer2157=== RUN TestGlobMatch2158=== PAUSE TestGlobMatch2159=== RUN TestValidateToken_ValidToken2160=== PAUSE TestValidateToken_ValidToken2161=== RUN TestValidateToken_WrongAudience2162=== PAUSE TestValidateToken_WrongAudience2163=== RUN TestValidateToken_Expired2164=== PAUSE TestValidateToken_Expired2165=== RUN TestValidateToken_BoundClaimsMismatch2166=== PAUSE TestValidateToken_BoundClaimsMismatch2167=== RUN TestValidateToken_BoundSubjectMismatch2168=== PAUSE TestValidateToken_BoundSubjectMismatch2169=== RUN TestValidateToken_MultipleProviders2170=== PAUSE TestValidateToken_MultipleProviders2171=== RUN TestValidateToken_NoMatchingProvider2172=== PAUSE TestValidateToken_NoMatchingProvider2173=== RUN TestValidateToken_KubernetesServiceAccount2174=== PAUSE TestValidateToken_KubernetesServiceAccount2175=== RUN TestNewValidator_KubernetesRequiresCA2176=== PAUSE TestNewValidator_KubernetesRequiresCA2177=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2178=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2179=== RUN TestPins_ReservedForMatchingRule2180=== PAUSE TestPins_ReservedForMatchingRule2181=== RUN TestPins_TopLevelShorthand2182=== PAUSE TestPins_TopLevelShorthand2183=== RUN TestPins_ConfigValidation2184=== PAUSE TestPins_ConfigValidation2185=== RUN TestScopes_LegacyProviderDefaultsToWrite2186=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2187=== RUN TestScopes_Rules2188=== PAUSE TestScopes_Rules2189=== RUN TestScopes_ConfigValidation2190=== PAUSE TestScopes_ConfigValidation2191=== CONT TestAudienceForIssuer2192--- PASS: TestAudienceForIssuer (0.00s)2193=== CONT TestPins_ConfigValidation2194=== CONT TestValidateToken_Expired2195=== CONT TestValidateToken_NoMatchingProvider2196=== CONT TestValidateToken_WrongAudience2197=== CONT TestValidateToken_ValidToken2198=== CONT TestGlobMatch2199=== RUN TestGlobMatch/foo_foo2200=== PAUSE TestGlobMatch/foo_foo2201=== RUN TestGlobMatch/foo_bar2202=== PAUSE TestGlobMatch/foo_bar2203=== RUN TestGlobMatch/*_2204=== PAUSE TestGlobMatch/*_2205=== RUN TestGlobMatch/*_anything2206=== PAUSE TestGlobMatch/*_anything2207=== RUN TestGlobMatch/foo*_foo2208=== PAUSE TestGlobMatch/foo*_foo2209=== RUN TestGlobMatch/foo*_foobar2210=== PAUSE TestGlobMatch/foo*_foobar2211=== RUN TestGlobMatch/foo*_bar2212=== PAUSE TestGlobMatch/foo*_bar2213=== RUN TestGlobMatch/*bar_bar2214=== PAUSE TestGlobMatch/*bar_bar2215=== RUN TestGlobMatch/*bar_foobar2216=== PAUSE TestGlobMatch/*bar_foobar2217=== RUN TestGlobMatch/*bar_foo2218=== PAUSE TestGlobMatch/*bar_foo2219=== RUN TestGlobMatch/foo*bar_foobar2220=== PAUSE TestGlobMatch/foo*bar_foobar2221=== RUN TestGlobMatch/foo*bar_foo123bar2222=== PAUSE TestGlobMatch/foo*bar_foo123bar2223=== RUN TestGlobMatch/foo*bar_foobarbaz2224=== PAUSE TestGlobMatch/foo*bar_foobarbaz2225=== RUN TestGlobMatch/*/*_foo/bar2226=== PAUSE TestGlobMatch/*/*_foo/bar2227=== RUN TestGlobMatch/*/*_foo2228=== PAUSE TestGlobMatch/*/*_foo2229=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2230=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2231=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02232=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02233=== RUN TestGlobMatch/refs/*/main_refs/heads/main2234=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2235=== RUN TestGlobMatch/fo?_foo2236=== PAUSE TestGlobMatch/fo?_foo2237=== RUN TestGlobMatch/fo?_fo2238=== PAUSE TestGlobMatch/fo?_fo2239=== RUN TestGlobMatch/fo?_fooo2240=== PAUSE TestGlobMatch/fo?_fooo2241=== RUN TestGlobMatch/?oo_foo2242=== PAUSE TestGlobMatch/?oo_foo2243=== RUN TestGlobMatch/?oo_boo2244=== PAUSE TestGlobMatch/?oo_boo2245=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2246=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2247=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2248=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2249=== CONT TestGlobMatch/foo_foo2250=== CONT TestScopes_Rules2251=== CONT TestGlobMatch/*/*_foo/bar2252=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2253=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2254=== CONT TestGlobMatch/?oo_boo2255=== CONT TestGlobMatch/?oo_foo2256=== CONT TestGlobMatch/fo?_fooo2257=== CONT TestGlobMatch/fo?_fo2258=== CONT TestGlobMatch/fo?_foo2259=== CONT TestGlobMatch/refs/*/main_refs/heads/main2260=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02261=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2262=== CONT TestGlobMatch/*/*_foo2263=== CONT TestGlobMatch/*bar_bar2264=== CONT TestGlobMatch/foo*bar_foobarbaz2265=== CONT TestGlobMatch/foo*bar_foo123bar2266=== CONT TestGlobMatch/foo*bar_foobar2267=== CONT TestGlobMatch/*bar_foo2268=== CONT TestGlobMatch/*bar_foobar2269=== CONT TestGlobMatch/foo*_foo2270=== CONT TestGlobMatch/foo*_bar2271=== CONT TestGlobMatch/foo*_foobar2272=== CONT TestGlobMatch/*_2273=== CONT TestGlobMatch/*_anything2274=== CONT TestGlobMatch/foo_bar2275--- PASS: TestGlobMatch (0.00s)2276 --- PASS: TestGlobMatch/foo_foo (0.00s)2277 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2278 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2279 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2280 --- PASS: TestGlobMatch/?oo_boo (0.00s)2281 --- PASS: TestGlobMatch/?oo_foo (0.00s)2282 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2283 --- PASS: TestGlobMatch/fo?_fo (0.00s)2284 --- PASS: TestGlobMatch/fo?_foo (0.00s)2285 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2286 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2287 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2288 --- PASS: TestGlobMatch/*/*_foo (0.00s)2289 --- PASS: TestGlobMatch/*bar_bar (0.00s)2290 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2291 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2292 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2293 --- PASS: TestGlobMatch/*bar_foo (0.00s)2294 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2295 --- PASS: TestGlobMatch/foo*_foo (0.00s)2296 --- PASS: TestGlobMatch/foo*_bar (0.00s)2297 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2298 --- PASS: TestGlobMatch/*_ (0.00s)2299 --- PASS: TestGlobMatch/*_anything (0.00s)2300 --- PASS: TestGlobMatch/foo_bar (0.00s)2301=== CONT TestScopes_ConfigValidation2302--- PASS: TestPins_ConfigValidation (0.00s)2303=== CONT TestValidateToken_BoundSubjectMismatch2304=== CONT TestValidateToken_KubernetesServiceAccount2305=== CONT TestValidateToken_MultipleProviders2306=== CONT TestPins_TopLevelShorthand2307--- PASS: TestScopes_ConfigValidation (0.00s)2308=== CONT TestValidateToken_BoundClaimsMismatch2309=== CONT TestPins_ReservedForMatchingRule2310=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2311=== CONT TestNewValidator_KubernetesRequiresCA2312=== CONT TestScopes_LegacyProviderDefaultsToWrite23132026/10/10 19:02:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63975/oidc23142026/10/10 19:02:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63973/oidc2315--- PASS: TestValidateToken_BoundSubjectMismatch (0.06s)23162026/10/10 19:02:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63978/oidc2317--- PASS: TestScopes_Rules (0.07s)2318--- PASS: TestValidateToken_BoundClaimsMismatch (0.06s)23192026/10/10 19:02:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63983/oidc23202026/10/10 19:02:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63986/oidc2321--- PASS: TestPins_TopLevelShorthand (0.07s)23222026/10/10 19:02:37 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:639822323--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.06s)23242026/10/10 19:02:37 http: TLS handshake error from 127.0.0.1:63981: read tcp 127.0.0.1:63977->127.0.0.1:63981: use of closed network connection2325--- PASS: TestNewValidator_KubernetesRequiresCA (0.06s)2326--- PASS: TestValidateToken_KubernetesServiceAccount (0.07s)23272026/10/10 19:02:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63988/oidc23282026/10/10 19:02:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63991/oidc23292026/10/10 19:02:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63993/oidc2330--- PASS: TestPins_ReservedForMatchingRule (0.08s)2331--- PASS: TestValidateToken_Expired (0.09s)2332--- PASS: TestValidateToken_ValidToken (0.09s)23332026/10/10 19:02:38 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323342026/10/10 19:02:38 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63996/oidc23352026/10/10 19:02:38 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:63998/oidc23362026/10/10 19:02:38 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:63990/oidc2337--- PASS: TestValidateToken_WrongAudience (0.13s)2338--- PASS: TestValidateToken_MultipleProviders (0.13s)2339--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.12s)23402026/10/10 19:02:38 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:63979/oidc2341--- PASS: TestValidateToken_NoMatchingProvider (0.16s)2342PASS2343Running hook tests...2344=== RUN TestSendPathsEmpty2345=== PAUSE TestSendPathsEmpty2346=== RUN TestQueueEnqueueAndFetch2347=== PAUSE TestQueueEnqueueAndFetch2348=== RUN TestQueueDeduplication2349=== PAUSE TestQueueDeduplication2350=== RUN TestQueueRemove2351=== PAUSE TestQueueRemove2352=== RUN TestQueueFetchBatchLimit2353=== PAUSE TestQueueFetchBatchLimit2354=== RUN TestQueueRetryMovesToBack2355=== PAUSE TestQueueRetryMovesToBack2356=== RUN TestQueueFetchRemoveLifecycle2357=== PAUSE TestQueueFetchRemoveLifecycle2358=== RUN TestQueueConcurrentWriters2359=== PAUSE TestQueueConcurrentWriters2360=== RUN TestQueueRemoveLargeClosure2361=== PAUSE TestQueueRemoveLargeClosure2362=== RUN TestServerClientIntegration2363--- PASS: TestServerClientIntegration (0.00s)2364=== RUN TestServerQueueError23652026/10/10 19:02:38 ERROR Failed to queue paths error="permission denied" count=12366--- PASS: TestServerQueueError (0.00s)2367=== RUN TestGetListenerSocketActivation2368 server_test.go:146: systemd socket activation does not exist on darwin2369--- SKIP: TestGetListenerSocketActivation (0.00s)2370=== RUN TestDrainIsolatesPoisonPath2371=== PAUSE TestDrainIsolatesPoisonPath2372=== RUN TestRunNotBlockedByPoisonHead2373=== PAUSE TestRunNotBlockedByPoisonHead2374=== RUN TestDrainGivesUpWhenServerDown2375=== PAUSE TestDrainGivesUpWhenServerDown2376=== RUN TestFailedPathPrunedByLaterClosure2377=== PAUSE TestFailedPathPrunedByLaterClosure2378=== RUN TestWorkerUploadsAndRemoves2379=== PAUSE TestWorkerUploadsAndRemoves2380=== RUN TestWorkerSkipsGCdPaths2381=== PAUSE TestWorkerSkipsGCdPaths2382=== RUN TestWorkerPrunesClosureDeps2383=== PAUSE TestWorkerPrunesClosureDeps2384=== RUN TestDrainTimeout2385=== PAUSE TestDrainTimeout2386=== CONT TestSendPathsEmpty2387=== CONT TestDrainIsolatesPoisonPath2388--- PASS: TestSendPathsEmpty (0.00s)2389=== CONT TestQueueRemoveLargeClosure2390=== CONT TestQueueConcurrentWriters2391=== CONT TestQueueFetchRemoveLifecycle2392=== CONT TestQueueRetryMovesToBack2393=== CONT TestQueueFetchBatchLimit2394=== CONT TestQueueRemove2395=== CONT TestQueueDeduplication2396=== CONT TestQueueEnqueueAndFetch2397=== CONT TestWorkerUploadsAndRemoves2398=== CONT TestDrainTimeout2399=== CONT TestWorkerPrunesClosureDeps2400=== CONT TestWorkerSkipsGCdPaths2401=== CONT TestFailedPathPrunedByLaterClosure2402=== CONT TestRunNotBlockedByPoisonHead2403=== CONT TestDrainGivesUpWhenServerDown24042026/10/10 19:02:38 INFO Upload queue status pending=224052026/10/10 19:02:38 INFO Upload queue status pending=224062026/10/10 19:02:38 INFO Uploading batch count=124072026/10/10 19:02:38 INFO Uploading batch count=124082026/10/10 19:02:38 ERROR Upload failed error="upload failed" count=124092026/10/10 19:02:38 INFO Upload queue status pending=32410--- PASS: TestQueueFetchBatchLimit (0.01s)24112026/10/10 19:02:38 INFO Uploading batch count=224122026/10/10 19:02:38 INFO Uploading batch count=124132026/10/10 19:02:38 ERROR Upload failed error="upload failed" count=12414--- PASS: TestQueueRetryMovesToBack (0.01s)24152026/10/10 19:02:38 INFO Upload queue status pending=224162026/10/10 19:02:38 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/7/scratch/0e971e34819014b9/build/TestWorkerSkipsGCdPaths2657033299/002/nonexistent2417--- PASS: TestQueueRemove (0.01s)24182026/10/10 19:02:38 INFO Uploading batch count=224192026/10/10 19:02:38 INFO Uploading batch count=124202026/10/10 19:02:38 INFO Uploading batch count=224212026/10/10 19:02:38 ERROR Upload failed error="upload failed" count=224222026/10/10 19:02:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0e971e34819014b9/build/TestDrainGivesUpWhenServerDown3261835085/002/a24232026/10/10 19:02:38 INFO Uploading batch count=12424--- PASS: TestQueueFetchRemoveLifecycle (0.01s)24252026/10/10 19:02:38 INFO Uploading batch count=124262026/10/10 19:02:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0e971e34819014b9/build/TestDrainGivesUpWhenServerDown3261835085/002/b24272026/10/10 19:02:38 INFO Uploading batch count=424282026/10/10 19:02:38 ERROR Upload failed error="upload failed" count=424292026/10/10 19:02:38 INFO Uploading batch count=224302026/10/10 19:02:38 ERROR Upload failed error="upload failed" count=224312026/10/10 19:02:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0e971e34819014b9/build/TestDrainGivesUpWhenServerDown3261835085/002/c24322026/10/10 19:02:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0e971e34819014b9/build/TestDrainGivesUpWhenServerDown3261835085/002/d24332026/10/10 19:02:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0e971e34819014b9/build/TestDrainIsolatesPoisonPath2800756431/002/bbb2434--- PASS: TestQueueDeduplication (0.02s)2435--- PASS: TestQueueEnqueueAndFetch (0.02s)24362026/10/10 19:02:38 INFO Uploading batch count=224372026/10/10 19:02:38 ERROR Upload failed error="upload failed" count=224382026/10/10 19:02:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0e971e34819014b9/build/TestDrainGivesUpWhenServerDown3261835085/002/e24392026/10/10 19:02:38 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0e971e34819014b9/build/TestDrainGivesUpWhenServerDown3261835085/002/f24402026/10/10 19:02:38 ERROR Drain finished with paths left in queue remaining=1024412026/10/10 19:02:38 INFO Uploading batch count=124422026/10/10 19:02:38 ERROR Upload failed error="upload failed" count=124432026/10/10 19:02:38 INFO Uploading batch count=124442026/10/10 19:02:38 ERROR Upload failed error="upload failed" count=124452026/10/10 19:02:38 INFO Uploading batch count=124462026/10/10 19:02:38 ERROR Upload failed error="upload failed" count=12447--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24482026/10/10 19:02:38 ERROR Drain finished with paths left in queue remaining=12449--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2450--- PASS: TestDrainIsolatesPoisonPath (0.02s)2451--- PASS: TestWorkerUploadsAndRemoves (0.03s)2452--- PASS: TestWorkerPrunesClosureDeps (0.03s)2453--- PASS: TestWorkerSkipsGCdPaths (0.03s)2454--- PASS: TestQueueRemoveLargeClosure (0.05s)2455--- PASS: TestQueueConcurrentWriters (0.16s)24562026/10/10 19:02:38 ERROR Upload failed error="context deadline exceeded" count=224572026/10/10 19:02:38 ERROR Drain finished with paths left in queue remaining=42458--- PASS: TestDrainTimeout (0.22s)24592026/10/10 19:02:39 INFO Uploading batch count=124602026/10/10 19:02:39 INFO Uploading batch count=124612026/10/10 19:02:39 INFO Uploading batch count=124622026/10/10 19:02:39 ERROR Upload failed error="upload failed" count=124632026/10/10 19:02:39 INFO Uploading batch count=124642026/10/10 19:02:39 ERROR Upload failed error="upload failed" count=124652026/10/10 19:02:39 INFO Uploading batch count=124662026/10/10 19:02:39 ERROR Upload failed error="upload failed" count=124672026/10/10 19:02:39 INFO Uploading batch count=124682026/10/10 19:02:39 ERROR Upload failed error="upload failed" count=124692026/10/10 19:02:39 ERROR Drain finished with paths left in queue remaining=12470--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2471PASS2472Running signing tests...2473=== RUN TestExternalSigner2474=== PAUSE TestExternalSigner2475=== RUN TestExternalSignerWrongPublicKey2476=== PAUSE TestExternalSignerWrongPublicKey2477=== RUN TestExternalSignerErrors2478=== PAUSE TestExternalSignerErrors2479=== RUN TestExternalSignerRestartsAfterCrash2480=== PAUSE TestExternalSignerRestartsAfterCrash2481=== RUN TestExternalSignerProgramErrorKeepsProcess2482=== PAUSE TestExternalSignerProgramErrorKeepsProcess2483=== RUN TestExternalSignerClose2484=== PAUSE TestExternalSignerClose2485=== RUN TestExternalSignerRejectsInvalidPublicKey2486=== PAUSE TestExternalSignerRejectsInvalidPublicKey2487=== RUN TestExternalSignerCancellation2488=== PAUSE TestExternalSignerCancellation2489=== RUN TestGenerateFingerprint2490=== PAUSE TestGenerateFingerprint2491=== RUN TestParseSigningKey2492=== PAUSE TestParseSigningKey2493=== RUN TestSign2494=== PAUSE TestSign2495=== RUN TestSignBatch2496=== PAUSE TestSignBatch2497=== RUN TestNilKeyPublicKey2498=== PAUSE TestNilKeyPublicKey2499=== RUN TestSignErrors2500=== PAUSE TestSignErrors2501=== CONT TestExternalSigner2502=== CONT TestExternalSignerCancellation2503=== CONT TestExternalSignerProgramErrorKeepsProcess2504=== CONT TestExternalSignerErrors2505=== CONT TestExternalSignerRestartsAfterCrash2506=== CONT TestExternalSignerRejectsInvalidPublicKey2507=== RUN TestExternalSignerErrors/exit_on_request2508=== RUN TestExternalSignerRejectsInvalidPublicKey/#002509=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002510=== CONT TestExternalSignerWrongPublicKey2511=== CONT TestSignBatch2512=== CONT TestSignErrors2513=== CONT TestNilKeyPublicKey2514--- PASS: TestNilKeyPublicKey (0.00s)2515=== CONT TestExternalSignerClose2516=== CONT TestParseSigningKey2517=== CONT TestSign2518=== CONT TestGenerateFingerprint2519=== RUN TestGenerateFingerprint/basic_with_references2520=== PAUSE TestExternalSignerErrors/exit_on_request2521=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2522=== RUN TestParseSigningKey/valid_32-byte_key2523=== RUN TestExternalSignerErrors/invalid_JSON2524=== PAUSE TestParseSigningKey/valid_32-byte_key2525=== PAUSE TestExternalSignerErrors/invalid_JSON2526=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2527=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2528=== PAUSE TestGenerateFingerprint/basic_with_references2529=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2530=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2531=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2532=== RUN TestGenerateFingerprint/no_references2533=== RUN TestExternalSignerErrors/wrong_shape2534=== PAUSE TestExternalSignerErrors/wrong_shape2535=== RUN TestParseSigningKey/no_colon2536=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2537=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2538=== PAUSE TestGenerateFingerprint/no_references2539=== RUN TestExternalSignerErrors/wrong_signatures_shape2540=== PAUSE TestParseSigningKey/no_colon2541=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2542=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2543=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2544=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2545=== RUN TestExternalSignerErrors/unrequested_key2546=== RUN TestParseSigningKey/empty_name2547=== PAUSE TestParseSigningKey/empty_name2548=== RUN TestParseSigningKey/invalid_base642549=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2550=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2551=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2552=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2553=== CONT TestExternalSignerRejectsInvalidPublicKey/#002554=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2555=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2556=== PAUSE TestExternalSignerErrors/unrequested_key2557=== PAUSE TestParseSigningKey/invalid_base642558=== RUN TestParseSigningKey/wrong_length2559=== RUN TestExternalSignerErrors/wrong_id2560=== RUN TestGenerateFingerprint/invalid_nar_hash_length2561=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2562=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2563=== RUN TestGenerateFingerprint/invalid_store_path_prefix2564--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2565 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2566 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2567 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2568 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2569 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2570=== PAUSE TestParseSigningKey/wrong_length2571=== CONT TestParseSigningKey/valid_32-byte_key2572=== CONT TestParseSigningKey/invalid_base642573=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2574=== CONT TestParseSigningKey/empty_name2575=== RUN TestGenerateFingerprint/invalid_reference_prefix2576=== CONT TestParseSigningKey/no_colon2577=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2578=== CONT TestGenerateFingerprint/basic_with_references2579=== CONT TestGenerateFingerprint/invalid_store_path_prefix2580=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2581=== CONT TestGenerateFingerprint/no_references2582=== CONT TestGenerateFingerprint/invalid_nar_hash_length2583=== PAUSE TestExternalSignerErrors/wrong_id2584=== RUN TestSignErrors/nil_key2585=== RUN TestExternalSignerErrors/null_signatures2586=== PAUSE TestSignErrors/nil_key2587=== PAUSE TestExternalSignerErrors/null_signatures2588=== CONT TestGenerateFingerprint/invalid_reference_prefix2589=== RUN TestExternalSignerErrors/wrong_signature_length2590=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2591=== RUN TestSignErrors/nil_narinfo2592=== PAUSE TestSignErrors/nil_narinfo2593--- PASS: TestSign (0.00s)2594=== CONT TestParseSigningKey/wrong_length2595=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2596=== RUN TestSignErrors/invalid_narinfo2597=== PAUSE TestExternalSignerErrors/wrong_signature_length2598=== RUN TestExternalSignerErrors/exit_at_startup2599--- PASS: TestGenerateFingerprint (0.00s)2600 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2601 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2602 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2603 --- PASS: TestGenerateFingerprint/no_references (0.00s)2604 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2605 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2606 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2607--- PASS: TestParseSigningKey (0.00s)2608 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2609 --- PASS: TestParseSigningKey/empty_name (0.00s)2610 --- PASS: TestParseSigningKey/no_colon (0.00s)2611 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2612 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2613 --- PASS: TestParseSigningKey/wrong_length (0.00s)2614=== PAUSE TestSignErrors/invalid_narinfo2615=== RUN TestSignErrors/canceled2616=== PAUSE TestSignErrors/canceled2617=== CONT TestSignErrors/nil_key2618=== PAUSE TestExternalSignerErrors/exit_at_startup2619=== RUN TestExternalSignerErrors/null2620=== PAUSE TestExternalSignerErrors/null2621=== RUN TestExternalSignerErrors/wrong_signature_name2622=== PAUSE TestExternalSignerErrors/wrong_signature_name2623=== RUN TestExternalSignerErrors/invalid_signature_base642624=== PAUSE TestExternalSignerErrors/invalid_signature_base642625=== RUN TestExternalSignerErrors/missing_signatures2626=== CONT TestSignErrors/invalid_narinfo2627=== PAUSE TestExternalSignerErrors/missing_signatures2628=== RUN TestExternalSignerErrors/too_few_signatures2629=== CONT TestSignErrors/canceled2630=== CONT TestSignErrors/nil_narinfo2631=== PAUSE TestExternalSignerErrors/too_few_signatures2632=== RUN TestExternalSignerErrors/missing_signature_name2633--- PASS: TestSignErrors (0.00s)2634 --- PASS: TestSignErrors/nil_key (0.00s)2635 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2636 --- PASS: TestSignErrors/canceled (0.00s)2637 --- PASS: TestSignErrors/nil_narinfo (0.00s)2638--- PASS: TestSignBatch (0.00s)2639=== PAUSE TestExternalSignerErrors/missing_signature_name2640=== RUN TestExternalSignerErrors/program_error2641=== PAUSE TestExternalSignerErrors/program_error2642=== CONT TestExternalSignerErrors/exit_on_request2643=== CONT TestExternalSignerErrors/exit_at_startup2644=== CONT TestExternalSignerErrors/unrequested_key2645=== CONT TestExternalSignerErrors/wrong_shape2646=== CONT TestExternalSignerErrors/invalid_JSON2647=== CONT TestExternalSignerErrors/wrong_signature_length2648=== CONT TestExternalSignerErrors/missing_signatures2649=== CONT TestExternalSignerErrors/null2650=== CONT TestExternalSignerErrors/wrong_signatures_shape2651=== CONT TestExternalSignerErrors/null_signatures2652=== CONT TestExternalSignerErrors/missing_signature_name2653=== CONT TestExternalSignerErrors/wrong_id2654=== CONT TestExternalSignerErrors/wrong_signature_name2655=== CONT TestExternalSignerErrors/too_few_signatures2656=== CONT TestExternalSignerErrors/program_error2657=== CONT TestExternalSignerErrors/invalid_signature_base642658--- PASS: TestExternalSigner (0.11s)2659--- PASS: TestExternalSignerRestartsAfterCrash (0.18s)2660/private/var/tb/7/scratch/0e971e34819014b9/build/TestExternalSignerRestartsAfterCrash3345902387/001/sign program: line 7: /private/var/tb/7/scratch/0e971e34819014b9/build/TestExternalSignerRestartsAfterCrash3345902387/001/sign program.starts: No such file or directory2661--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.24s)2662--- PASS: TestExternalSignerClose (0.32s)2663--- PASS: TestExternalSignerWrongPublicKey (0.39s)2664--- PASS: TestExternalSignerCancellation (0.48s)2665--- PASS: TestExternalSignerErrors (0.01s)2666 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.54s)2667 --- PASS: TestExternalSignerErrors/null (0.61s)2668 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.68s)2669 --- PASS: TestExternalSignerErrors/exit_on_request (0.76s)2670 --- PASS: TestExternalSignerErrors/too_few_signatures (0.83s)2671 --- PASS: TestExternalSignerErrors/null_signatures (0.91s)2672 --- PASS: TestExternalSignerErrors/missing_signature_name (0.98s)2673 --- PASS: TestExternalSignerErrors/program_error (1.05s)2674 --- PASS: TestExternalSignerErrors/wrong_id (1.13s)2675 --- PASS: TestExternalSignerErrors/wrong_shape (1.21s)2676 --- PASS: TestExternalSignerErrors/unrequested_key (1.28s)2677 --- PASS: TestExternalSignerErrors/missing_signatures (1.35s)2678 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.43s)2679 --- PASS: TestExternalSignerErrors/invalid_JSON (1.51s)2680 --- PASS: TestExternalSignerErrors/exit_at_startup (1.58s)2681 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.66s)2682PASS2683Running OpenBao signer tests...2684=== RUN TestSign2685=== PAUSE TestSign2686=== RUN TestSignErrors2687=== PAUSE TestSignErrors2688=== RUN TestServe2689=== PAUSE TestServe2690=== RUN TestServeRejectsGarbage2691=== PAUSE TestServeRejectsGarbage2692=== CONT TestSign2693=== CONT TestServeRejectsGarbage2694=== CONT TestSignErrors2695=== CONT TestServe2696=== RUN TestSignErrors/http_error2697--- PASS: TestServeRejectsGarbage (0.00s)2698=== PAUSE TestSignErrors/http_error2699=== RUN TestSignErrors/invalid_json2700=== PAUSE TestSignErrors/invalid_json2701=== RUN TestSignErrors/no_prefix2702=== PAUSE TestSignErrors/no_prefix2703=== RUN TestSignErrors/invalid_base642704=== PAUSE TestSignErrors/invalid_base642705=== CONT TestSignErrors/http_error2706=== CONT TestSignErrors/no_prefix2707=== CONT TestSignErrors/invalid_base642708=== CONT TestSignErrors/invalid_json2709--- PASS: TestServe (0.00s)2710--- PASS: TestSign (0.00s)2711--- PASS: TestSignErrors (0.00s)2712 --- PASS: TestSignErrors/http_error (0.00s)2713 --- PASS: TestSignErrors/no_prefix (0.00s)2714 --- PASS: TestSignErrors/invalid_json (0.00s)2715 --- PASS: TestSignErrors/invalid_base64 (0.00s)2716PASS