niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #432
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.17s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestDoWithRetry_BodyReplayedViaGetBody117=== CONT TestGetStorePathHash118=== RUN TestGetStorePathHash/valid_store_path119=== CONT TestDumpPathWriterError120=== CONT TestResolveStorePath121=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer122=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess123=== CONT TestRateLimiterFeedback124=== RUN TestRateLimiterFeedback/429_enables_limiter125=== PAUSE TestRateLimiterFeedback/429_enables_limiter126=== RUN TestRateLimiterFeedback/503_enables_limiter127=== PAUSE TestRateLimiterFeedback/503_enables_limiter128=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter129=== CONT TestPathInfoCACompatibility130=== CONT TestConvertHashToNix32131=== RUN TestConvertHashToNix32/SRI_format_to_Nix32132=== CONT TestEncodeNixBase32WithRealHash133--- PASS: TestEncodeNixBase32WithRealHash (0.00s)134=== CONT TestSetClientTLSDoesNotMutateDefaultTransport135=== CONT TestEncodeNixBase321362026/10/25 19:00:54 WARN Rate limiter enabled after throttle name=server-test rate=5137=== RUN TestEncodeNixBase32/test_string_hash138=== CONT TestSetClientTLS139=== CONT TestScriptTokenEmptyCommand140=== CONT TestScriptTokenScriptFails141=== CONT TestScriptTokenBadJSON142=== CONT TestScriptTokenEmptyToken143=== CONT TestScriptTokenCachesUntilRefresh144=== CONT TestScriptTokenNoExpiryRerunsEveryCall145=== CONT TestFileTokenEmpty146=== CONT TestFileTokenMissing147=== CONT TestFileTokenReadsAndCaches148=== CONT TestStaticToken149=== CONT TestSetClientTLSErrors150=== PAUSE TestGetStorePathHash/valid_store_path151=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter152=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter153=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32154=== RUN TestPathInfoCACompatibility/null_ca_field155=== PAUSE TestEncodeNixBase32/test_string_hash156--- PASS: TestScriptTokenEmptyCommand (0.00s)157--- PASS: TestResolveStorePath (0.00s)158=== CONT TestParsePathInfoJSON159=== RUN TestParsePathInfoJSON/Nix_format160=== CONT TestParsePathInfoJSONMultiplePaths161=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths162=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter163--- PASS: TestFileTokenEmpty (0.00s)164--- PASS: TestStaticToken (0.00s)165--- PASS: TestDoServerRequestAttachesToken (0.00s)166--- PASS: TestFileTokenReadsAndCaches (0.00s)167=== CONT TestDumpPathSingleFile168=== RUN TestConvertHashToNix32/already_Nix32_format169=== RUN TestEncodeNixBase32/empty_input170=== PAUSE TestEncodeNixBase32/empty_input171=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths172=== CONT TestUploadMultipart_SupersededByPeer173=== RUN TestUploadMultipart_SupersededByPeer/exists174=== CONT TestDumpPathMatchesNix175=== RUN TestGetStorePathHash/basename_without_hyphen_should_error176=== CONT TestSupersededNARStillUploadsListing177=== RUN TestSupersededNARStillUploadsListing/small_NAR178=== PAUSE TestParsePathInfoJSON/Nix_format179--- PASS: TestFileTokenMissing (0.00s)180=== CONT TestPartSizeForNAR181=== RUN TestPartSizeForNAR/zero_stays_at_minimum182=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum183=== RUN TestPartSizeForNAR/small_stays_at_minimum184=== PAUSE TestPartSizeForNAR/small_stays_at_minimum185=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum186=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum187=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts188=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts189=== RUN TestPartSizeForNAR/1_TiB190=== PAUSE TestPartSizeForNAR/1_TiB191=== RUN TestPartSizeForNAR/5_TiB_S3_max_object192=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object193=== RUN TestPartSizeForNAR/capped_at_5_GiB194=== PAUSE TestPartSizeForNAR/capped_at_5_GiB195=== PAUSE TestUploadMultipart_SupersededByPeer/exists196=== CONT TestPathInfoHashCompatibility197=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)198=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)199=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon2002026/10/25 19:00:54 WARN Rate limiter enabled after throttle name=server-test rate=52012026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:54660202=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon203=== PAUSE TestPathInfoCACompatibility/null_ca_field204=== RUN TestPathInfoCACompatibility/old_string_format_-_text205=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI206=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI207=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512208=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512209=== RUN TestUploadMultipart_SupersededByPeer/missing210=== PAUSE TestUploadMultipart_SupersededByPeer/missing211--- PASS: TestScriptTokenScriptFails (0.00s)212=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text213=== CONT TestUploadMultipart_FailedPartBufferNotReused214=== CONT TestUploadMultipart_PartsInParallel2152026/10/25 19:00:54 WARN Rate limiter backed off name=server-test rate=52162026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:54660217=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun218=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive219=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive220=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error221=== PAUSE TestConvertHashToNix32/already_Nix32_format222=== CONT TestFilterOversizedClosures223=== RUN TestSetClientTLS/rejects_connection_without_client_cert224=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error225=== RUN TestFilterOversizedClosures/no_limit_keeps_everything226=== RUN TestConvertHashToNix32/invalid_format227--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)228=== CONT TestRegisterUploadedObjectReusesConnections229=== RUN TestParsePathInfoJSON/Lix_format230=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths231=== RUN TestSetClientTLSErrors/missing_cert_file232=== PAUSE TestSupersededNARStillUploadsListing/small_NAR233=== RUN TestPathInfoCACompatibility/new_structured_format_-_text234=== CONT TestCaseHackSuffix235=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error236=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error237=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error238=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica2392026/10/25 19:00:54 INFO Garbage collection started240=== PAUSE TestSetClientTLSErrors/missing_cert_file241=== RUN TestSupersededNARStillUploadsListing/dump_cut_short242=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything243=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped244=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped245=== RUN TestFilterOversizedClosures/all_closures_skipped246=== PAUSE TestFilterOversizedClosures/all_closures_skipped247=== RUN TestSetClientTLSErrors/missing_key_file248=== PAUSE TestSetClientTLSErrors/missing_key_file249=== RUN TestSetClientTLSErrors/missing_ca_file250=== PAUSE TestSetClientTLSErrors/missing_ca_file251=== RUN TestSetClientTLSErrors/invalid_ca_file252=== PAUSE TestSetClientTLSErrors/invalid_ca_file253=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short254=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails255=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails256=== CONT TestStreamPushStopsWhenCanceled257=== CONT TestClientSignaturesByStorePath258--- PASS: TestStreamPushStopsWhenCanceled (0.00s)259=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths260=== PAUSE TestConvertHashToNix32/invalid_format261--- PASS: TestClientSignaturesByStorePath (0.00s)262=== CONT TestStreamPushReportsSkippedPaths263=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text264--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)265=== CONT TestShellSplitErrors266--- PASS: TestShellSplitErrors (0.00s)267=== CONT TestStreamPushBatchesUnderLoad268--- PASS: TestStreamPushReportsSkippedPaths (0.00s)269=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert270=== CONT TestStreamPushReportsSignatures2712026/10/25 19:00:54 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=0272=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method273=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method274=== CONT TestStreamPushIsolatesFailures2752026/10/25 19:00:54 INFO Garbage collection started2762026/10/25 19:00:54 ERROR Upload failed error="bad path" count=32772026/10/25 19:00:54 ERROR Upload failed error=boom count=1278=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry279=== CONT TestRetryTimeoutOutlastsMaxRetries280=== CONT TestStreamPushGivesUpOnDeadServer281=== CONT TestStreamPushRequestLine2822026/10/25 19:00:54 ERROR Upload failed error="connection refused" count=202832026/10/25 19:00:54 ERROR Server seems unavailable, giving up on batch untried=17284=== CONT TestPartSizeForNAR/zero_stays_at_minimum285=== CONT TestPartSizeForNAR/1_TiB286=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts287=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum288=== CONT TestPartSizeForNAR/small_stays_at_minimum289=== CONT TestPartSizeForNAR/capped_at_5_GiB290=== CONT TestPartSizeForNAR/5_TiB_S3_max_object291=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)292=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512293=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon294=== CONT TestUploadMultipart_SupersededByPeer/exists295=== PAUSE TestParsePathInfoJSON/Lix_format296=== RUN TestParsePathInfoJSON/empty_input297=== PAUSE TestParsePathInfoJSON/empty_input298=== RUN TestParsePathInfoJSON/whitespace_only299=== PAUSE TestParsePathInfoJSON/whitespace_only300=== RUN TestParsePathInfoJSON/invalid_JSON301=== PAUSE TestParsePathInfoJSON/invalid_JSON302=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI303=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter304=== CONT TestStreamPushReportsEveryPath305=== CONT TestRateLimiterFeedback/429_enables_limiter306=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA307=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA308=== RUN TestSetClientTLS/preserves_debug_logging_transport309=== PAUSE TestSetClientTLS/preserves_debug_logging_transport3102026/10/25 19:00:54 WARN Garbage collection finished on another replica. Its statistics are not available here311=== CONT TestEncodeNixBase32/test_string_hash312=== CONT TestEncodeNixBase32/empty_input313=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter314=== CONT TestUploadMultipart_SupersededByPeer/missing3152026/10/25 19:00:54 WARN Rate limiter enabled after throttle name=s3-test rate=53162026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:546993172026/10/25 19:00:54 ERROR Upload failed error=boom count=13182026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:54692319=== CONT TestDoWithRetry_FinalResponseBodyReadable320=== CONT TestShellSplit321=== CONT TestRateLimiterFeedback/503_enables_limiter322--- PASS: TestStreamPushReportsSignatures (0.00s)323=== CONT TestGetStorePathHash/valid_store_path324--- PASS: TestStreamPushIsolatesFailures (0.00s)325=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error326=== CONT TestGetStorePathHash/basename_without_hyphen_should_error327=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error328--- PASS: TestScriptTokenBadJSON (0.02s)329=== CONT TestFilterOversizedClosures/no_limit_keeps_everything330=== CONT TestSetClientTLSErrors/missing_cert_file331=== CONT TestSetClientTLSErrors/missing_key_file332=== CONT TestSetClientTLSErrors/invalid_ca_file333=== CONT TestSetClientTLSErrors/missing_ca_file334=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3352026/10/25 19:00:54 INFO Uploading abc-hello (1.0GB)336--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)3372026/10/25 19:00:54 WARN Rate limiter enabled after throttle name=server-test rate=53382026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:54736339=== CONT TestSupersededNARStillUploadsListing/small_NAR340--- PASS: TestPartSizeForNAR (0.00s)341 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)342 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)343 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)344 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)345 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)346 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)347 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)348--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)349--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)350--- PASS: TestScriptTokenEmptyToken (0.02s)351--- PASS: TestShellSplit (0.00s)352--- PASS: TestStreamPushReportsEveryPath (0.00s)3532026/10/25 19:00:54 INFO Uploading abc-hello (1.0GB)354--- PASS: TestEncodeNixBase32 (0.00s)355 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)356 --- PASS: TestEncodeNixBase32/empty_input (0.00s)357--- PASS: TestGetStorePathHash (0.01s)358 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)359 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)360 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)361 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)362--- PASS: TestPathInfoHashCompatibility (0.00s)363 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)364 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)365 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)366 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)367--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)368=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths369=== CONT TestSupersededNARStillUploadsListing/dump_cut_short370--- PASS: TestSetClientTLSErrors (0.02s)371 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)372 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)373 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)374 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)3752026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:54692376=== CONT TestFilterOversizedClosures/all_closures_skipped3772026/10/25 19:00:54 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=50378=== CONT TestConvertHashToNix32/invalid_format379=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths380--- PASS: TestParsePathInfoJSONMultiplePaths (0.02s)381 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)382 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)383--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)384 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)385 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)386=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3872026/10/25 19:00:54 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=2000388--- PASS: TestFilterOversizedClosures (0.00s)389 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)390 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)391 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)392=== CONT TestPathInfoCACompatibility/null_ca_field393=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive394=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method395=== CONT TestConvertHashToNix32/already_Nix32_format396=== CONT TestPathInfoCACompatibility/new_structured_format_-_text397=== CONT TestParsePathInfoJSON/Nix_format398=== CONT TestParsePathInfoJSON/invalid_JSON399=== CONT TestParsePathInfoJSON/whitespace_only400=== CONT TestParsePathInfoJSON/empty_input401=== CONT TestPathInfoCACompatibility/old_string_format_-_text402--- PASS: TestPathInfoCACompatibility (0.02s)403 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)404 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)405 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)406 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)407 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)408=== CONT TestParsePathInfoJSON/Lix_format409--- PASS: TestParsePathInfoJSON (0.02s)410 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)411 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)412 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)413 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)414 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)415=== CONT TestSetClientTLS/rejects_connection_without_client_cert4162026/10/25 19:00:54 WARN Rate limiter backed off name=server-test rate=5417=== CONT TestSetClientTLS/preserves_debug_logging_transport418=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA4192026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:54692420=== CONT TestConvertHashToNix32/SRI_format_to_Nix32421--- PASS: TestConvertHashToNix32 (0.02s)422 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)423 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)424 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)4252026/10/25 19:00:54 WARN Rate limiter enabled after throttle name=s3-test rate=54262026/10/25 19:00:54 WARN Rate limiter enabled after throttle name=server-test rate=54272026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:547504282026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:546924292026/10/25 19:00:54 WARN Rate limiter backed off name=server-test rate=54302026/10/25 19:00:54 WARN Rate limiter enabled after throttle name=server-test rate=54312026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:547554322026/10/25 19:00:54 WARN Rate limiter backed off name=server-test rate=5433--- PASS: TestRateLimiterFeedback (0.01s)434 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)435 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)436 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)437 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)438--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)4392026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:54692440--- PASS: TestStreamPushRequestLine (0.02s)4412026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:546924422026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:546924432026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:546924442026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:546924452026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:546924462026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:54692447--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)4482026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:546924492026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:546924502026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:54692451--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)4522026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:546924532026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:54692454--- PASS: TestDumpPathWriterError (0.06s)455--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)4562026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:546924572026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:54692458--- PASS: TestDumpPathSingleFile (0.06s)4592026/10/25 19:00:54 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:54692460--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.04s)4612026/10/25 19:00:54 http: TLS handshake error from 127.0.0.1:54768: remote error: tls: bad certificate462--- PASS: TestSetClientTLS (0.02s)463 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)464 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)465 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)466--- PASS: TestCaseHackSuffix (0.06s)4672026/10/25 19:00:54 INFO Uploading abc-hello (1.0GB)4682026/10/25 19:00:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:54764/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:54764/part/24692026/10/25 19:00:54 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"470--- PASS: TestDumpPathMatchesNix (0.10s)471--- PASS: TestStreamPushBatchesUnderLoad (0.10s)472--- PASS: TestSupersededNARStillUploadsListing (0.01s)473 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)474 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.01s)475 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.56s)476--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.58s)477--- PASS: TestUploadMultipart_PartsInParallel (0.62s)4782026/10/25 19:00:55 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:54661/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:54661/api/uploads/complete4792026/10/25 19:00:55 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4802026/10/25 19:00:55 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:54661/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:54661/api/uploads/complete481--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4822026/10/25 19:00:55 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4832026/10/25 19:00:55 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:54661/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:54661/api/uploads/complete4842026/10/25 19:00:55 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"485--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)486PASS487Running server tests...488The files belonging to this database system will be owned by user "_tribuchetbld1".489This user must also own the server process.490491The database cluster will be initialized with locale "C".492The default database encoding has accordingly been set to "SQL_ASCII".493The default text search configuration will be set to "english".494495Data page checksums are enabled.496497creating directory /private/var/tb/1/scratch/b566a4a9a208906d/build/postgres2405675912/data ... ok498creating subdirectories ... ok499selecting dynamic shared memory implementation ... posix500selecting default "max_connections" ... 100501selecting default "shared_buffers" ... 128MB502selecting default time zone ... UTC503creating configuration files ... ok504running bootstrap script ... ok505performing post-bootstrap initialization ... ok506syncing data to disk ... ok507508initdb: warning: enabling "trust" authentication for local connections509initdb: 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.510511Success. You can now start the database server using:512513 pg_ctl -D /private/var/tb/1/scratch/b566a4a9a208906d/build/postgres2405675912/data -l logfile start514515/private/var/tb/1/scratch/b566a4a9a208906d/build/postgres2405675912:5432 - no response5162026-10-25 19:00:56.668 UTC [18144] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5172026-10-25 19:00:56.668 UTC [18144] LOG: listening on Unix socket "/private/var/tb/1/scratch/b566a4a9a208906d/build/postgres2405675912/.s.PGSQL.5432"5182026-10-25 19:00:56.671 UTC [18151] LOG: database system was shut down at 2026-10-25 19:00:56 UTC5192026-10-25 19:00:56.671 UTC [18144] LOG: database system is ready to accept connections520/private/var/tb/1/scratch/b566a4a9a208906d/build/postgres2405675912:5432 - accepting connections521{"timestamp":"2026-10-25T19:00:56.925591Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"ed52a1a6-b5a7-4f3a-bdcc-b2c2e8f364a1","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":9,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}522{"timestamp":"2026-10-25T19:00:57.033725Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"1f6b2d18-e38c-4899-9bc6-97832f62d630","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}523{"timestamp":"2026-10-25T19:00:57.137269Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"34bc5310-fef3-4a9d-96fe-651c7e78f6b4","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}524=== RUN TestService_AuthMiddleware525=== PAUSE TestService_AuthMiddleware526=== RUN TestService_AuthMiddleware_MTLSProxyHeader527=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader528=== RUN TestService_AuthMiddleware_MTLSBoundSubjects529=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects530=== RUN TestService_ReadAuthMiddleware531=== PAUSE TestService_ReadAuthMiddleware532=== RUN TestService_AuthMiddleware_OIDC533=== PAUSE TestService_AuthMiddleware_OIDC534=== RUN TestService_RequireScope_OIDC535=== PAUSE TestService_RequireScope_OIDC536=== RUN TestService_ReadScope_PublicByDefault537=== PAUSE TestService_ReadScope_PublicByDefault538=== RUN TestCacheConfigHandler539=== PAUSE TestCacheConfigHandler540=== RUN TestCacheStatsHandler541=== PAUSE TestCacheStatsHandler542=== RUN TestClientCADerivations543=== PAUSE TestClientCADerivations544=== RUN TestClientErrorHandling545=== PAUSE TestClientErrorHandling546=== RUN TestClientIntegration547=== PAUSE TestClientIntegration548=== RUN TestClientMultipleUploads549=== PAUSE TestClientMultipleUploads550=== RUN TestClientWithDependencies551=== PAUSE TestClientWithDependencies552=== RUN TestClientSharedPathCommittedMidPush553=== PAUSE TestClientSharedPathCommittedMidPush554=== RUN TestPinProtectsFromGC555=== PAUSE TestPinProtectsFromGC556=== RUN TestClientPushesUseOnePush557=== PAUSE TestClientPushesUseOnePush558=== RUN TestClientFallsBackToClosures559=== PAUSE TestClientFallsBackToClosures560=== RUN TestDeleteClosuresRacingPins561=== PAUSE TestDeleteClosuresRacingPins562=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock563=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock564=== RUN TestResolveDBConnectionString565=== PAUSE TestResolveDBConnectionString566=== RUN TestConnectWaitsForAPeerMigration567=== PAUSE TestConnectWaitsForAPeerMigration568=== RUN TestLeadElectsOneAndHandsOver569=== PAUSE TestLeadElectsOneAndHandsOver570=== RUN TestLeadIncumbentWinsAfterRestart5712026/10/25 19:00:57 INFO lead: acquired remote=192.0.2.1:12345722026/10/25 19:00:58 INFO lead: released remote=192.0.2.1:12345732026/10/25 19:00:58 INFO lead: acquired remote=192.0.2.1:12345742026/10/25 19:00:59 INFO lead: released remote=192.0.2.1:1234575--- PASS: TestLeadIncumbentWinsAfterRestart (1.93s)576=== RUN TestLeadIncumbentAnnouncesAtOnce577=== PAUSE TestLeadIncumbentAnnouncesAtOnce578=== RUN TestLeadEndsOnShutdown579=== PAUSE TestLeadEndsOnShutdown580=== RUN TestLeadEndsWhenItsConnectionHangs5812026/10/25 19:00:59 INFO lead: acquired remote=192.0.2.1:12345822026-10-25 19:01:00.547 UTC [18187] FATAL: terminating connection due to administrator command5832026/10/25 19:01:00 INFO lead: acquired remote=192.0.2.1:12345842026/10/25 19:01:01 WARN lead: lock connection lost error="timeout: context deadline exceeded"5852026/10/25 19:01:01 INFO lead: released remote=192.0.2.1:12345862026/10/25 19:01:01 INFO lead: released remote=192.0.2.1:1234587--- PASS: TestLeadEndsWhenItsConnectionHangs (2.77s)588=== RUN TestGCAdvisoryLockBlocksConcurrentRun589=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun590=== RUN TestGCBugBareHashReferences591=== PAUSE TestGCBugBareHashReferences592=== RUN TestGCMetrics593=== PAUSE TestGCMetrics594=== RUN TestPushDedupSurvivesConcurrentGC595=== PAUSE TestPushDedupSurvivesConcurrentGC596=== RUN TestDeduplicatedObjectsRecordedAsPending597=== PAUSE TestDeduplicatedObjectsRecordedAsPending598=== RUN TestGCSweepSkipsPendingObjects599=== PAUSE TestGCSweepSkipsPendingObjects600=== RUN TestTombstonedObjectOfferedWithoutWaiting601=== PAUSE TestTombstonedObjectOfferedWithoutWaiting602=== RUN TestGCSweepDeliversEachKeyOnce603=== PAUSE TestGCSweepDeliversEachKeyOnce604=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection605=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection606=== RUN TestForceGCDuringPushOffersSweptObject607=== PAUSE TestForceGCDuringPushOffersSweptObject608=== RUN TestFailedS3DeleteKeepsTombstone609=== PAUSE TestFailedS3DeleteKeepsTombstone610=== RUN TestSweepSkipsRowsLockedByPush611=== PAUSE TestSweepSkipsRowsLockedByPush612=== RUN TestRegisterCompletedObjectNeedsPendingRow613=== PAUSE TestRegisterCompletedObjectNeedsPendingRow614=== RUN TestGetExistingObjectsLocksRows615=== PAUSE TestGetExistingObjectsLocksRows616=== RUN TestSweepRechecksPendingAfterLocking617=== PAUSE TestSweepRechecksPendingAfterLocking618=== RUN TestPushWaitsForSweepHoldingRow619=== PAUSE TestPushWaitsForSweepHoldingRow620=== RUN TestCommitRacingPendingCleanupKeepsObjects621=== PAUSE TestCommitRacingPendingCleanupKeepsObjects622=== RUN TestGCEndsOnShutdown623=== PAUSE TestGCEndsOnShutdown624=== RUN TestGCTaskStore_StartNew625=== PAUSE TestGCTaskStore_StartNew626=== RUN TestGCTaskStore_DeduplicateSameParams627=== PAUSE TestGCTaskStore_DeduplicateSameParams628=== RUN TestGCTaskStore_ConflictDifferentParams629=== PAUSE TestGCTaskStore_ConflictDifferentParams630=== RUN TestGCTaskStore_GetEmpty631=== PAUSE TestGCTaskStore_GetEmpty632=== RUN TestGCTaskStore_GetReturnsLatest633=== PAUSE TestGCTaskStore_GetReturnsLatest634=== RUN TestGCTaskStore_CompletedAllowsNewTask635=== PAUSE TestGCTaskStore_CompletedAllowsNewTask636=== RUN TestGCTaskStore_PhaseUpdates637=== PAUSE TestGCTaskStore_PhaseUpdates638=== RUN TestGCTaskStore_Fail639=== PAUSE TestGCTaskStore_Fail640=== RUN TestGracefulShutdownDrainsInflight641=== PAUSE TestGracefulShutdownDrainsInflight642=== RUN TestService_healthCheckHandler643=== PAUSE TestService_healthCheckHandler644=== RUN TestService_readinessHandler645=== PAUSE TestService_readinessHandler646=== RUN TestGenerateLandingPage647=== PAUSE TestGenerateLandingPage648=== RUN TestCacheConfigHandlerMaxNarSize649=== PAUSE TestCacheConfigHandlerMaxNarSize650=== RUN TestCreatePendingClosureRejectsOversizedNAR651=== PAUSE TestCreatePendingClosureRejectsOversizedNAR652=== RUN TestNARDeduplicationMetadataUploadBug653=== PAUSE TestNARDeduplicationMetadataUploadBug654=== RUN TestMetricsInventory655=== PAUSE TestMetricsInventory656=== RUN TestMetricsCommit657=== PAUSE TestMetricsCommit658=== RUN TestService_NativeMTLS659=== PAUSE TestService_NativeMTLS660=== RUN TestServerTLSConfig661=== PAUSE TestServerTLSConfig662=== RUN TestMultipartCleanup663=== PAUSE TestMultipartCleanup664=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded665=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded666=== RUN TestPendingCleanupUsesOneCutoff667=== PAUSE TestPendingCleanupUsesOneCutoff668=== RUN TestObjectStatsTrigger669=== PAUSE TestObjectStatsTrigger670=== RUN TestObjectStatsUpdatedOncePerCommit671=== PAUSE TestObjectStatsUpdatedOncePerCommit672=== RUN TestOrphanedObjectsGC673=== PAUSE TestOrphanedObjectsGC674=== RUN TestOrphanedObjectsGCStressTest675=== PAUSE TestOrphanedObjectsGCStressTest676=== RUN TestCreatePin_ReservedPins677=== PAUSE TestCreatePin_ReservedPins678=== RUN TestPresentReportsOnlyClosureRoots679=== PAUSE TestPresentReportsOnlyClosureRoots680=== RUN TestPresentRefreshesOnlyStaleClosures681=== PAUSE TestPresentRefreshesOnlyStaleClosures682=== RUN TestPresentNotReportedWhileGCDeletesClosure683=== PAUSE TestPresentNotReportedWhileGCDeletesClosure684=== RUN TestParseSingleRange685=== PAUSE TestParseSingleRange686=== RUN TestProxyHeadersOnlyTrustedOnSocket6872026/10/25 19:01:02 INFO Starting HTTP server address=proxy.sock6882026/10/25 19:01:02 INFO Starting HTTP server address=127.0.0.1:548056892026/10/25 19:01:02 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6902026/10/25 19:01:02 INFO Shutdown signal received, draining in-flight requests timeout=10s691--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)692=== RUN TestIsValidCachePath693=== PAUSE TestIsValidCachePath694=== RUN TestReadProxyNarinfo695=== PAUSE TestReadProxyNarinfo696=== RUN TestReadProxyNarinfoAlreadyDecompressed697=== PAUSE TestReadProxyNarinfoAlreadyDecompressed698=== RUN TestReadProxyContentNegotiation699=== PAUSE TestReadProxyContentNegotiation700=== RUN TestReadProxyNarStreaming701=== PAUSE TestReadProxyNarStreaming702=== RUN TestReadProxy404703=== PAUSE TestReadProxy404704=== RUN TestReadProxyInvalidPath705=== PAUSE TestReadProxyInvalidPath706=== RUN TestReadProxyHead707=== PAUSE TestReadProxyHead708=== RUN TestReadProxyOutlastsServerWriteTimeout709=== PAUSE TestReadProxyOutlastsServerWriteTimeout710=== RUN TestReadProxyConditionalGet711=== PAUSE TestReadProxyConditionalGet712=== RUN TestReadProxyRootRedirectsToIndexHTML713=== PAUSE TestReadProxyRootRedirectsToIndexHTML714=== RUN TestReadProxyDisabled715=== PAUSE TestReadProxyDisabled716=== RUN TestReadRedirectNar717=== PAUSE TestReadRedirectNar718=== RUN TestReadRedirectKeepsNarinfoProxied719=== PAUSE TestReadRedirectKeepsNarinfoProxied720=== RUN TestReadProxyRangeRequest721=== PAUSE TestReadProxyRangeRequest722=== RUN TestReadRedirectUsesPublicS3URL723=== PAUSE TestReadRedirectUsesPublicS3URL724=== RUN TestPush_OverlappingRootsStoreOneRowPerKey725=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey726=== RUN TestPush_CompleteCommitsEveryRoot727=== PAUSE TestPush_CompleteCommitsEveryRoot728=== RUN TestPush_RepeatedRootCommitsOnce729=== PAUSE TestPush_RepeatedRootCommitsOnce730=== RUN TestPush_CompleteWaitsForCleanupOfThePush731=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush732=== RUN TestPush_RootsAreLockedInByteOrder733=== PAUSE TestPush_RootsAreLockedInByteOrder734=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit735=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit736=== RUN TestPush_RejectsBadRequests737=== PAUSE TestPush_RejectsBadRequests738=== RUN TestPush_SignsNarinfosOfItsPendingObjects739=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects740=== RUN TestRedundantMultipartUpload741=== PAUSE TestRedundantMultipartUpload742=== RUN TestCompleteMultipartUpload_ErrorButObjectExists743=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists744=== RUN TestCompletedNarNotReofferedAcrossClosures745=== PAUSE TestCompletedNarNotReofferedAcrossClosures746=== RUN TestPresignedUploadRegisteredBeforeCommit747=== PAUSE TestPresignedUploadRegisteredBeforeCommit748=== RUN TestService_Rustfstest749=== PAUSE TestService_Rustfstest750=== RUN TestParseSize751=== PAUSE TestParseSize752=== RUN TestSkippedUploadsHandler753=== PAUSE TestSkippedUploadsHandler754=== RUN TestSystemdListenerNotActivated755--- PASS: TestSystemdListenerNotActivated (0.00s)756=== RUN TestWatchdogBeatsWhenHealthy757--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)758=== RUN TestWatchdogSkipsWhenUnhealthy7592026/10/25 19:01:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/25 19:01:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/25 19:01:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7622026/10/25 19:01:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/25 19:01:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/25 19:01:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/25 19:01:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/10/25 19:01:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/10/25 19:01:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/10/25 19:01:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"769--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)770=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle771=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle772=== RUN TestProxyWriteTimeout773=== PAUSE TestProxyWriteTimeout774=== RUN TestPendingClosureWriteTimeout775=== PAUSE TestPendingClosureWriteTimeout776=== RUN TestIsValidUploadKey777=== PAUSE TestIsValidUploadKey778=== RUN TestUploadHandlersRejectInvalidKeys779=== PAUSE TestUploadHandlersRejectInvalidKeys780=== RUN TestUploadHandlersRejectOversizedBody781=== PAUSE TestUploadHandlersRejectOversizedBody782=== RUN TestService_cleanupPendingClosuresHandler783=== PAUSE TestService_cleanupPendingClosuresHandler784=== RUN TestService_createPendingClosureHandler785=== PAUSE TestService_createPendingClosureHandler786=== RUN TestService_verifyS3Integrity787=== PAUSE TestService_verifyS3Integrity788=== RUN TestCompleteMultipartUnregistered789=== PAUSE TestCompleteMultipartUnregistered790=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT791=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT792=== CONT TestReadProxy404793=== CONT TestCreatePin_ReservedPins794=== CONT TestService_AuthMiddleware795=== CONT TestCompleteMultipartUnregistered796=== CONT TestReadProxyNarStreaming797=== CONT TestReadProxyNarinfoAlreadyDecompressed798=== CONT TestReadProxyNarinfo799=== CONT TestIsValidCachePath800=== CONT TestParseSingleRange801=== RUN TestIsValidCachePath/narinfo802=== CONT TestPresentNotReportedWhileGCDeletesClosure803=== PAUSE TestIsValidCachePath/narinfo804=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars805=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars806=== RUN TestIsValidCachePath/nar_zst807=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale808=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale809=== CONT TestPresentReportsOnlyClosureRoots810=== CONT TestRedundantMultipartUpload811=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT812=== CONT TestService_verifyS3Integrity813=== CONT TestService_createPendingClosureHandler814=== CONT TestService_cleanupPendingClosuresHandler815=== CONT TestUploadHandlersRejectOversizedBody816=== CONT TestUploadHandlersRejectInvalidKeys817=== CONT TestIsValidUploadKey818=== CONT TestPendingClosureWriteTimeout819=== CONT TestProxyWriteTimeout820=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle821=== RUN TestPendingClosureWriteTimeout/empty822=== RUN TestParseSingleRange/none823=== RUN TestIsValidUploadKey/narinfo824=== CONT TestReadProxyContentNegotiation825=== PAUSE TestIsValidCachePath/nar_zst826=== RUN TestProxyWriteTimeout/narinfo827=== RUN TestIsValidCachePath/nar_xz828=== PAUSE TestProxyWriteTimeout/narinfo829=== RUN TestProxyWriteTimeout/1_GiB_nar830=== PAUSE TestProxyWriteTimeout/1_GiB_nar831=== RUN TestProxyWriteTimeout/10_GiB_nar832=== PAUSE TestIsValidCachePath/nar_xz833=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh834=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh835=== CONT TestPresentRefreshesOnlyStaleClosures836=== CONT TestSkippedUploadsHandler837=== PAUSE TestPendingClosureWriteTimeout/empty838=== PAUSE TestParseSingleRange/none839=== PAUSE TestIsValidUploadKey/narinfo840=== RUN TestIsValidUploadKey/nar_zst841=== PAUSE TestIsValidUploadKey/nar_zst842=== RUN TestIsValidUploadKey/nar_xz843=== RUN TestParseSingleRange/unknown_unit844=== PAUSE TestIsValidUploadKey/nar_xz845=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info846=== RUN TestIsValidCachePath/nar_bz2847=== RUN TestPendingClosureWriteTimeout/400_objects848=== PAUSE TestProxyWriteTimeout/10_GiB_nar849=== RUN TestIsValidUploadKey/nar_plain8502026/10/25 19:01:02 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000851=== PAUSE TestParseSingleRange/unknown_unit852=== RUN TestParseSingleRange/multi-range_ignored853=== PAUSE TestParseSingleRange/multi-range_ignored854=== RUN TestParseSingleRange/malformed_no_dash855=== PAUSE TestParseSingleRange/malformed_no_dash856=== RUN TestParseSingleRange/malformed_both_empty857=== PAUSE TestParseSingleRange/malformed_both_empty858=== RUN TestParseSingleRange/malformed_end_before_start859=== PAUSE TestParseSingleRange/malformed_end_before_start860=== RUN TestParseSingleRange/closed861=== PAUSE TestParseSingleRange/closed862=== RUN TestParseSingleRange/open-ended863=== PAUSE TestParseSingleRange/open-ended864=== RUN TestParseSingleRange/end_clamped_to_size865=== PAUSE TestParseSingleRange/end_clamped_to_size866=== RUN TestParseSingleRange/suffix867=== PAUSE TestParseSingleRange/suffix868=== RUN TestParseSingleRange/suffix_exceeds_size869=== PAUSE TestParseSingleRange/suffix_exceeds_size870=== RUN TestParseSingleRange/single_byte871=== PAUSE TestParseSingleRange/single_byte872=== RUN TestParseSingleRange/start_past_EOF873=== PAUSE TestParseSingleRange/start_past_EOF874=== RUN TestParseSingleRange/start_far_past_EOF875=== PAUSE TestParseSingleRange/start_far_past_EOF876=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info877=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal878=== CONT TestParseSize879=== PAUSE TestPendingClosureWriteTimeout/400_objects880--- PASS: TestParseSize (0.00s)881=== PAUSE TestIsValidUploadKey/nar_plain882=== CONT TestService_Rustfstest883=== RUN TestPendingClosureWriteTimeout/670k_objects884=== PAUSE TestPendingClosureWriteTimeout/670k_objects885=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline886=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline887=== PAUSE TestIsValidCachePath/nar_bz2888=== RUN TestIsValidCachePath/nar_uncompressed889=== PAUSE TestIsValidCachePath/nar_uncompressed890=== RUN TestIsValidCachePath/ls891=== PAUSE TestIsValidCachePath/ls892=== RUN TestIsValidCachePath/log893=== PAUSE TestIsValidCachePath/log894=== RUN TestIsValidCachePath/realisation895=== PAUSE TestIsValidCachePath/realisation896=== RUN TestIsValidCachePath/nix-cache-info897=== PAUSE TestIsValidCachePath/nix-cache-info898=== RUN TestIsValidCachePath/index.html899=== PAUSE TestIsValidCachePath/index.html900=== RUN TestIsValidCachePath/traversal_parent901=== PAUSE TestIsValidCachePath/traversal_parent902=== RUN TestProxyWriteTimeout/unknown_size903=== CONT TestPresignedUploadRegisteredBeforeCommit904=== PAUSE TestProxyWriteTimeout/unknown_size905=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal906=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key907=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key908=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key909=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key910=== CONT TestCompletedNarNotReofferedAcrossClosures911=== RUN TestIsValidUploadKey/listing912=== PAUSE TestIsValidUploadKey/listing913=== RUN TestIsValidUploadKey/build_log914=== PAUSE TestIsValidUploadKey/build_log915=== RUN TestIsValidUploadKey/build_log_home-manager_file916=== PAUSE TestIsValidUploadKey/build_log_home-manager_file917=== RUN TestIsValidUploadKey/build_log_plus_in_name918=== PAUSE TestIsValidUploadKey/build_log_plus_in_name919=== RUN TestIsValidUploadKey/build_log_question_mark920=== PAUSE TestIsValidUploadKey/build_log_question_mark921=== RUN TestIsValidUploadKey/build_log_equals922=== PAUSE TestIsValidUploadKey/build_log_equals923=== RUN TestIsValidUploadKey/realisation924=== PAUSE TestIsValidUploadKey/realisation925=== RUN TestIsValidUploadKey/realisation_plus_in_output926=== PAUSE TestIsValidUploadKey/realisation_plus_in_output927=== RUN TestIsValidUploadKey/nix-cache-info928=== PAUSE TestIsValidUploadKey/nix-cache-info929=== RUN TestIsValidUploadKey/index.html930=== PAUSE TestIsValidUploadKey/index.html931=== RUN TestIsValidUploadKey/narinfo_key,_nar_type932=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type933=== RUN TestIsValidUploadKey/nar_key,_narinfo_type934=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type935=== RUN TestIsValidUploadKey/listing_key,_narinfo_type936=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type937=== RUN TestIsValidUploadKey/traversal938=== PAUSE TestIsValidUploadKey/traversal939=== RUN TestIsValidUploadKey/traversal_nar940=== PAUSE TestIsValidUploadKey/traversal_nar941=== RUN TestIsValidUploadKey/absolute942=== PAUSE TestIsValidUploadKey/absolute943=== RUN TestIsValidUploadKey/empty_key944=== PAUSE TestIsValidUploadKey/empty_key945=== RUN TestIsValidUploadKey/unknown_type946=== PAUSE TestIsValidUploadKey/unknown_type947=== CONT TestCompleteMultipartUpload_ErrorButObjectExists948=== RUN TestIsValidCachePath/traversal_in_middle949=== PAUSE TestIsValidCachePath/traversal_in_middle950=== RUN TestIsValidCachePath/invalid_char_e951=== PAUSE TestIsValidCachePath/invalid_char_e952=== RUN TestIsValidCachePath/invalid_char_u953=== PAUSE TestIsValidCachePath/invalid_char_u954=== RUN TestIsValidCachePath/random_path955=== PAUSE TestIsValidCachePath/random_path956=== RUN TestIsValidCachePath/empty957=== PAUSE TestIsValidCachePath/empty958=== RUN TestIsValidCachePath/leading_slash959=== PAUSE TestIsValidCachePath/leading_slash960=== RUN TestIsValidCachePath/wrong_extension961=== PAUSE TestIsValidCachePath/wrong_extension962=== RUN TestIsValidCachePath/short_hash963=== PAUSE TestIsValidCachePath/short_hash964=== CONT TestReadRedirectUsesPublicS3URL965=== CONT TestPush_SignsNarinfosOfItsPendingObjects966--- PASS: TestSkippedUploadsHandler (0.05s)967=== CONT TestPush_RejectsBadRequests9682026/10/25 19:01:02 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54808/oidc969=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure970=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure971=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart972=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart973=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts974=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts975=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit9762026/10/25 19:01:03 INFO Received cleanup request method=DELETE path=/api/pending_closures9772026/10/25 19:01:03 INFO Aborted multipart uploads count=0 kept=09782026/10/25 19:01:03 INFO Received uploads request method=POST path=/api/pending_closures9792026/10/25 19:01:03 INFO Received cleanup request method=DELETE path=/api/pending_closures9802026/10/25 19:01:03 INFO Aborted multipart uploads count=1 kept=09812026/10/25 19:01:03 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9822026/10/25 19:01:03 INFO Received uploads request method=POST path=/api/pending_closures9832026/10/25 19:01:03 INFO Received uploads request method=POST path=/api/pending_closures9842026/10/25 19:01:03 INFO Received uploads request method=POST path=/api/pending_closures9852026-10-25 19:01:03.244 UTC [18245] ERROR: Closure does not exist: id=19862026-10-25 19:01:03.244 UTC [18245] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9872026-10-25 19:01:03.244 UTC [18245] STATEMENT: -- name: CommitPendingClosure :one988 SELECT commit_pending_closure($1::bigint)::bigint989 990--- PASS: TestService_cleanupPendingClosuresHandler (0.89s)991=== CONT TestPush_RootsAreLockedInByteOrder992--- PASS: TestReadProxyNarStreaming (1.21s)993=== CONT TestPush_CompleteWaitsForCleanupOfThePush9942026/10/25 19:01:04 INFO Received uploads request method=POST path=/api/pending_closures995--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.18s)996=== CONT TestPush_RepeatedRootCommitsOnce997--- PASS: TestReadProxy404 (2.34s)998=== CONT TestPush_CompleteCommitsEveryRoot9992026/10/25 19:01:04 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1000--- PASS: TestService_AuthMiddleware (2.37s)1001=== CONT TestPush_OverlappingRootsStoreOneRowPerKey10022026/10/25 19:01:05 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10032026/10/25 19:01:05 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MmE4NTkwOTQtNTQ4Ni00ZmI4LTlmMGUtOTJjMTdlOTliNzdlLjk5ODZlZWRiLTAxNDUtNDk0Ni04ZjllLTgwNDJlODgwOWJhYngxNzkyOTU0ODYzMjk2NzgyMDAw parts=1010042026/10/25 19:01:05 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10052026/10/25 19:01:05 INFO Completed upload id=1 objects=2 duration=10.910875ms10062026/10/25 19:01:05 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001007--- PASS: TestPresentReportsOnlyClosureRoots (2.81s)1008=== CONT TestReadProxyRootRedirectsToIndexHTML10092026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures10102026/10/25 19:01:05 INFO Starting cleanup of old closures method=DELETE path=/api/closures10112026/10/25 19:01:05 INFO Aborted multipart uploads count=0 kept=010122026/10/25 19:01:05 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=010132026/10/25 19:01:05 INFO Vacuumed table table=pending_closures10142026/10/25 19:01:05 INFO Vacuumed table table=pending_objects10152026/10/25 19:01:05 INFO Vacuumed table table=multipart_uploads10162026/10/25 19:01:05 INFO Vacuumed table table=closures10172026/10/25 19:01:05 INFO Vacuumed table table=objects10182026/10/25 19:01:05 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001019--- PASS: TestService_createPendingClosureHandler (2.98s)1020=== CONT TestReadProxyRangeRequest10212026/10/25 19:01:05 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1022--- PASS: TestReadProxyNarinfo (3.14s)1023=== CONT TestReadRedirectKeepsNarinfoProxied1024--- PASS: TestReadProxyNarinfoAlreadyDecompressed (3.28s)1025=== CONT TestFailedS3DeleteKeepsTombstone10262026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures10272026/10/25 19:01:05 INFO Received uploads request method=POST path=/api/pending_closures10282026/10/25 19:01:06 INFO Received uploads request method=POST path=/api/pending_closures1029--- PASS: TestReadProxyContentNegotiation (4.13s)1030=== CONT TestReadRedirectNar10312026/10/25 19:01:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10322026/10/25 19:01:06 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1033--- PASS: TestCompleteMultipartUnregistered (4.29s)1034=== CONT TestReadProxyDisabled10352026/10/25 19:01:06 INFO Received push request method=POST path=/api/pushes10362026/10/25 19:01:07 INFO Received complete push request method=POST path=/api/pushes/1/complete10372026/10/25 19:01:07 INFO Completed push id=1 objects=4 duration=34.448791ms10382026/10/25 19:01:07 INFO Received push request method=POST path=/api/pushes10392026/10/25 19:01:07 INFO Aborted multipart uploads count=0 kept=010402026/10/25 19:01:07 WARN Force mode enabled - objects will be deleted immediately without grace period10412026/10/25 19:01:07 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=010422026/10/25 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures10432026/10/25 19:01:07 INFO Vacuumed table table=pending_closures10442026/10/25 19:01:07 INFO Vacuumed table table=pending_objects10452026/10/25 19:01:07 INFO Vacuumed table table=multipart_uploads10462026/10/25 19:01:07 INFO Vacuumed table table=closures10472026/10/25 19:01:07 INFO Vacuumed table table=objects10482026/10/25 19:01:07 INFO Received complete push request method=POST path=/api/pushes/2/complete10492026/10/25 19:01:07 INFO Completed push id=2 objects=4 duration=8.021041ms1050--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (4.88s)1051=== CONT TestOrphanedObjectsGCStressTest10522026/10/25 19:01:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10532026/10/25 19:01:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10542026/10/25 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures10552026/10/25 19:01:07 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MmE4NTkwOTQtNTQ4Ni00ZmI4LTlmMGUtOTJjMTdlOTliNzdlLjE0MDU4NmYwLTVkNDMtNDE2ZS05ODk0LWFiMWM2ZGZlZGM0MngxNzkyOTU0ODY1ODA2MjYwMDAw parts=1210562026/10/25 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures10572026/10/25 19:01:07 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MmE4NTkwOTQtNTQ4Ni00ZmI4LTlmMGUtOTJjMTdlOTliNzdlLmFhNDdiMzFjLTQxYTYtNGUzZi04NWViLWJlMTI4OGM5MGJhMHgxNzkyOTU0ODY2MDczMTAzMDAw parts=1010582026/10/25 19:01:07 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10592026/10/25 19:01:07 INFO Completed upload id=1 objects=2 duration=21.263958ms10602026/10/25 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures10612026/10/25 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures10622026/10/25 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures10632026/10/25 19:01:07 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10642026/10/25 19:01:07 WARN Found objects in DB but missing from S3, will re-upload count=11065--- PASS: TestService_verifyS3Integrity (5.39s)1066=== CONT TestGracefulShutdownDrainsInflight10672026/10/25 19:01:07 INFO Starting HTTP server address=127.0.0.1:5487310682026/10/25 19:01:07 INFO Shutdown signal received, draining in-flight requests timeout=10s10692026/10/25 19:01:07 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10702026/10/25 19:01:07 INFO Received uploads request method=POST path=/api/pending_closures1071--- PASS: TestPresignedUploadRegisteredBeforeCommit (5.38s)1072=== CONT TestService_healthCheckHandler1073--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1074=== CONT TestGCTaskStore_Fail1075--- PASS: TestGCTaskStore_Fail (0.00s)1076=== CONT TestOrphanedObjectsGC1077--- PASS: TestService_Rustfstest (5.50s)1078=== CONT TestGCTaskStore_PhaseUpdates1079--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1080=== CONT TestObjectStatsUpdatedOncePerCommit1081--- PASS: TestReadRedirectUsesPublicS3URL (5.78s)1082=== CONT TestGCTaskStore_CompletedAllowsNewTask1083--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1084=== CONT TestObjectStatsTrigger10852026/10/25 19:01:08 INFO Received uploads request method=POST path=/api/pending_closures10862026/10/25 19:01:08 INFO Received uploads request method=POST path=/api/pending_closures10872026/10/25 19:01:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1088=== RUN TestPush_RejectsBadRequests/no_roots1089=== PAUSE TestPush_RejectsBadRequests/no_roots1090=== RUN TestPush_RejectsBadRequests/no_objects1091=== PAUSE TestPush_RejectsBadRequests/no_objects1092=== RUN TestPush_RejectsBadRequests/bad_root1093=== PAUSE TestPush_RejectsBadRequests/bad_root1094=== RUN TestPush_RejectsBadRequests/root_not_in_objects1095=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1096=== CONT TestGCTaskStore_GetReturnsLatest1097--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1098=== CONT TestPendingCleanupUsesOneCutoff10992026/10/25 19:01:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11002026/10/25 19:01:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11012026/10/25 19:01:09 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MmE4NTkwOTQtNTQ4Ni00ZmI4LTlmMGUtOTJjMTdlOTliNzdlLjE1NzQ1NDA2LTM3NTUtNGUyZC1hNzUyLTUwMzg4OWQzM2UwMngxNzkyOTU0ODY4ODQ5MDI3MDAw11022026/10/25 19:01:09 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MmE4NTkwOTQtNTQ4Ni00ZmI4LTlmMGUtOTJjMTdlOTliNzdlLmUwOWU5ZDlmLTU1NmMtNDkwYi05ZjZiLTkwMGQ2OTcxNDgxNXgxNzkyOTU0ODY3Mjg5MDQ1MDAw parts=1211032026/10/25 19:01:09 INFO Received uploads request method=POST path=/api/pending_closures1104--- PASS: TestCompletedNarNotReofferedAcrossClosures (6.81s)1105=== CONT TestGCTaskStore_GetEmpty1106--- PASS: TestGCTaskStore_GetEmpty (0.00s)1107=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded11082026/10/25 19:01:09 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MmE4NTkwOTQtNTQ4Ni00ZmI4LTlmMGUtOTJjMTdlOTliNzdlLjE1NzQ1NDA2LTM3NTUtNGUyZC1hNzUyLTUwMzg4OWQzM2UwMngxNzkyOTU0ODY4ODQ5MDI3MDAw parts=11109--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (6.82s)1110=== CONT TestGCTaskStore_ConflictDifferentParams1111--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1112=== CONT TestMultipartCleanup11132026/10/25 19:01:09 INFO Received push request method=POST path=/api/pushes11142026/10/25 19:01:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11152026/10/25 19:01:09 INFO Signed narinfos id=1 count=111162026/10/25 19:01:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11172026/10/25 19:01:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11182026/10/25 19:01:09 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"11192026/10/25 19:01:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11202026/10/25 19:01:09 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"11212026/10/25 19:01:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11222026/10/25 19:01:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11232026/10/25 19:01:09 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=111242026/10/25 19:01:09 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11252026/10/25 19:01:09 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1126--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (7.13s)1127=== CONT TestServerTLSConfig1128=== RUN TestServerTLSConfig/no_client_CA1129=== PAUSE TestServerTLSConfig/no_client_CA1130=== RUN TestServerTLSConfig/missing_CA_file1131=== PAUSE TestServerTLSConfig/missing_CA_file1132=== RUN TestServerTLSConfig/not_a_PEM_file1133=== PAUSE TestServerTLSConfig/not_a_PEM_file1134=== CONT TestGCTaskStore_DeduplicateSameParams1135--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1136=== CONT TestGCTaskStore_StartNew1137--- PASS: TestGCTaskStore_StartNew (0.00s)1138=== CONT TestService_NativeMTLS11392026/10/25 19:01:09 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MmE4NTkwOTQtNTQ4Ni00ZmI4LTlmMGUtOTJjMTdlOTliNzdlLjMzNDdlNDViLTVjMjEtNDA1OS04Nzc4LTliMjA4YmI3NjNhMXgxNzkyOTU0ODY3NzQ1NTIzMDAw error="Get \"http://127.0.0.1:1/bucket13/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11402026/10/25 19:01:09 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MmE4NTkwOTQtNTQ4Ni00ZmI4LTlmMGUtOTJjMTdlOTliNzdlLjQ5NTNjZTJhLTczZDctNGFkMi05MzBiLTk1ZmExMjdjMzdlNHgxNzkyOTU0ODY3Njk5MDIwMDAw parts=1211412026/10/25 19:01:09 INFO Received cleanup request method=DELETE path=/api/pending_closures11422026/10/25 19:01:09 INFO Aborted multipart uploads count=1 kept=01143--- PASS: TestRedundantMultipartUpload (7.31s)1144=== CONT TestMetricsCommit11452026/10/25 19:01:09 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11462026/10/25 19:01:09 WARN Refused reserved pin name=worker-x86_64-linux11472026/10/25 19:01:09 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11482026/10/25 19:01:09 INFO Received create pin request method=POST path=/api/pins/my-app11492026/10/25 19:01:09 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1150--- PASS: TestCreatePin_ReservedPins (7.43s)1151=== CONT TestMetricsInventory1152--- PASS: TestPresentRefreshesOnlyStaleClosures (7.78s)1153=== CONT TestNARDeduplicationMetadataUploadBug11542026/10/25 19:01:10 INFO Received push request method=POST path=/api/pushes11552026-10-25 19:01:10.557 UTC [18334] ERROR: could not obtain lock on row in relation "closures"11562026-10-25 19:01:10.557 UTC [18334] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11572026-10-25 19:01:10.558 UTC [18334] ERROR: could not obtain lock on row in relation "closures"11582026-10-25 19:01:10.558 UTC [18334] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11592026-10-25 19:01:10.559 UTC [18334] ERROR: could not obtain lock on row in relation "closures"11602026-10-25 19:01:10.559 UTC [18334] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11612026-10-25 19:01:10.567 UTC [18334] ERROR: could not obtain lock on row in relation "closures"11622026-10-25 19:01:10.567 UTC [18334] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11632026-10-25 19:01:10.568 UTC [18334] ERROR: could not obtain lock on row in relation "closures"11642026-10-25 19:01:10.568 UTC [18334] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1165--- PASS: TestPush_RootsAreLockedInByteOrder (7.38s)1166=== CONT TestGetExistingObjectsLocksRows11672026/10/25 19:01:10 INFO Received push request method=POST path=/api/pushes11682026/10/25 19:01:10 INFO Received push request method=POST path=/api/pushes11692026/10/25 19:01:11 INFO Received complete push request method=POST path=/api/pushes/1/complete11702026/10/25 19:01:11 INFO Completed push id=1 objects=4 duration=28.537833ms1171--- PASS: TestPush_RepeatedRootCommitsOnce (6.55s)1172=== CONT TestRegisterCompletedObjectNeedsPendingRow11732026-10-25 19:01:11.091 UTC [18337] ERROR: Push does not exist: id=111742026-10-25 19:01:11.091 UTC [18337] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11752026-10-25 19:01:11.091 UTC [18337] STATEMENT: SELECT commit_push($1)1176--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (7.53s)1177=== CONT TestSweepSkipsRowsLockedByPush11782026/10/25 19:01:11 INFO Received push request method=POST path=/api/pushes11792026/10/25 19:01:11 INFO Received complete push request method=POST path=/api/pushes/1/complete11802026/10/25 19:01:11 INFO Completed push id=1 objects=6 duration=31.163958ms1181--- PASS: TestPush_CompleteCommitsEveryRoot (6.71s)1182=== CONT TestSweepRechecksPendingAfterLocking11832026/10/25 19:01:11 INFO Received push request method=POST path=/api/pushes1184--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.98s)1185=== CONT TestCreatePendingClosureRejectsOversizedNAR11862026/10/25 19:01:11 INFO Received uploads request method=POST path=/api/pending_closures1187--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1188=== CONT TestCommitRacingPendingCleanupKeepsObjects1189--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.70s)1190=== CONT TestPushWaitsForSweepHoldingRow1191--- PASS: TestReadRedirectKeepsNarinfoProxied (6.66s)1192=== CONT TestCacheConfigHandlerMaxNarSize1193--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1194=== CONT TestGCEndsOnShutdown1195=== RUN TestGCEndsOnShutdown/before_the_run1196=== PAUSE TestGCEndsOnShutdown/before_the_run1197=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1198=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1199=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1200=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1201=== CONT TestGenerateLandingPage1202--- PASS: TestGenerateLandingPage (0.00s)1203=== CONT TestReadProxyOutlastsServerWriteTimeout1204--- PASS: TestReadProxyRangeRequest (7.07s)1205=== CONT TestReadProxyConditionalGet12062026/10/25 19:01:12 INFO Received uploads request method=POST path=/api/pending_closures12072026/10/25 19:01:12 INFO Aborted multipart uploads count=0 kept=012082026/10/25 19:01:12 WARN Force mode enabled - objects will be deleted immediately without grace period12092026/10/25 19:01:12 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12102026/10/25 19:01:12 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1211--- PASS: TestFailedS3DeleteKeepsTombstone (7.26s)1212=== CONT TestService_readinessHandler1213--- PASS: TestReadRedirectNar (6.48s)1214=== CONT TestReadProxyHead1215--- PASS: TestReadProxyDisabled (6.57s)1216=== CONT TestReadProxyInvalidPath12172026/10/25 19:01:13 WARN Rate limiter enabled after throttle name=s3-test rate=512182026/10/25 19:01:13 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1219=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1220 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101221 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001222--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (10.89s)1223=== CONT TestClientCADerivations1224--- PASS: TestObjectStatsUpdatedOncePerCommit (6.20s)1225=== CONT TestDeleteClosuresRacingPins1226--- PASS: TestService_healthCheckHandler (6.36s)1227=== CONT TestForceGCDuringPushOffersSweptObject1228=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1229=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1230=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1231=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1232=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1233--- PASS: TestObjectStatsTrigger (6.51s)1234=== CONT TestGCSweepDeliversEachKeyOnce12352026/10/25 19:01:14 INFO Received uploads request method=POST path=/api/pending_closures12362026/10/25 19:01:15 INFO Received uploads request method=POST path=/api/pending_closures12372026/10/25 19:01:15 INFO Received cleanup request method=DELETE path=/api/pending_closures12382026/10/25 19:01:15 INFO Received uploads request method=POST path=/api/pending_closures1239--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (6.16s)1240=== CONT TestTombstonedObjectOfferedWithoutWaiting12412026/10/25 19:01:15 INFO Received uploads request method=POST path=/api/pending_closures12422026/10/25 19:01:15 INFO Received cleanup request method=DELETE path=/api/pending_closures12432026/10/25 19:01:15 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket46/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12442026/10/25 19:01:15 INFO Aborted multipart uploads count=0 kept=112452026/10/25 19:01:15 INFO Received cleanup request method=DELETE path=/api/pending_closures12462026/10/25 19:01:15 INFO Aborted multipart uploads count=1 kept=01247--- PASS: TestMultipartCleanup (6.64s)1248=== CONT TestGCSweepSkipsPendingObjects12492026/10/25 19:01:15 INFO Received push request method=POST path=/api/pushes12502026/10/25 19:01:16 INFO Received complete push request method=POST path=/api/pushes/1/complete1251=== NAME TestOrphanedObjectsGC1252 orphaned_objects_gc_test.go:287: GC Test Summary:1253 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1254 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1255 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1256 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1257 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1258--- PASS: TestOrphanedObjectsGC (8.58s)1259=== CONT TestDeduplicatedObjectsRecordedAsPending12602026/10/25 19:01:16 INFO Completed push id=1 objects=4 duration=41.825375ms12612026/10/25 19:01:16 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12622026/10/25 19:01:16 INFO Completed upload id=2 objects=2 duration=696.875µs1263--- PASS: TestMetricsCommit (6.78s)1264=== CONT TestPushDedupSurvivesConcurrentGC12652026/10/25 19:01:16 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12662026/10/25 19:01:16 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1267--- PASS: TestService_NativeMTLS (6.98s)1268=== CONT TestClientFallsBackToClosures1269--- PASS: TestMetricsInventory (7.12s)1270=== CONT TestGCMetrics1271--- PASS: TestGetExistingObjectsLocksRows (6.75s)1272=== CONT TestGCBugBareHashReferences1273=== NAME TestNARDeduplicationMetadataUploadBug1274 metadata_upload_test.go:48: First store path: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestNARDeduplicationMetadataUploadBug531039756/001/store/497q89grhhiahmk6zza47lijj66mlw6r-file1.txt12752026/10/25 19:01:17 INFO Received push request method=POST path=/api/pushes12762026/10/25 19:01:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12772026/10/25 19:01:17 INFO Uploading 497q89grhhiahmk6zza47lijj66mlw6r-file1.txt (160B)12782026/10/25 19:01:17 WARN Failed to register uploaded object key=497q89grhhiahmk6zza47lijj66mlw6r.ls error="server returned 404: 404 page not found\n"1279--- PASS: TestRegisterCompletedObjectNeedsPendingRow (6.49s)1280=== CONT TestGCAdvisoryLockBlocksConcurrentRun12812026/10/25 19:01:17 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12822026/10/25 19:01:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12832026/10/25 19:01:17 INFO Signed narinfos id=1 count=112842026/10/25 19:01:17 INFO Uploading 1 narinfos12852026/10/25 19:01:17 INFO Received complete push request method=POST path=/api/pushes/1/complete12862026/10/25 19:01:17 WARN Failed to register uploaded object key=497q89grhhiahmk6zza47lijj66mlw6r.narinfo error="server returned 404: 404 page not found\n"12872026/10/25 19:01:17 INFO Completed push id=1 objects=3 duration=17.836375ms12882026/10/25 19:01:17 INFO Upload complete. (214ms)1289=== NAME TestNARDeduplicationMetadataUploadBug1290 metadata_upload_test.go:54: Retrieved narinfo from S3:1291 StorePath: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestNARDeduplicationMetadataUploadBug531039756/001/store/497q89grhhiahmk6zza47lijj66mlw6r-file1.txt1292 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1293 Compression: zstd1294 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1295 NarSize: 1601296 References: 1297 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1298 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1299 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1300 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1301 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/1/scratch/b566a4a9a208906d/build/TestNARDeduplicationMetadataUploadBug531039756/001/store/baxqsiqy8b2429bvs777s923w90an468-file2.txt13022026/10/25 19:01:17 INFO Received push request method=POST path=/api/pushes13032026/10/25 19:01:17 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13042026/10/25 19:01:17 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13052026/10/25 19:01:17 WARN Failed to register uploaded object key=baxqsiqy8b2429bvs777s923w90an468.ls error="server returned 404: 404 page not found\n"13062026/10/25 19:01:17 INFO Signed narinfos id=2 count=113072026/10/25 19:01:17 INFO Aborted multipart uploads count=0 kept=013082026/10/25 19:01:17 INFO Uploading 1 narinfos13092026/10/25 19:01:17 WARN Force mode enabled - objects will be deleted immediately without grace period13102026/10/25 19:01:17 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=013112026/10/25 19:01:17 INFO Vacuumed table table=pending_closures13122026/10/25 19:01:17 INFO Vacuumed table table=pending_objects13132026/10/25 19:01:17 INFO Vacuumed table table=multipart_uploads13142026/10/25 19:01:17 INFO Received complete push request method=POST path=/api/pushes/2/complete13152026/10/25 19:01:17 WARN Failed to register uploaded object key=baxqsiqy8b2429bvs777s923w90an468.narinfo error="server returned 404: 404 page not found\n"13162026/10/25 19:01:17 INFO Vacuumed table table=closures13172026/10/25 19:01:17 INFO Completed push id=2 objects=3 duration=930.875µs13182026/10/25 19:01:17 INFO Upload complete. (190ms)1319 metadata_upload_test.go:76: Retrieved narinfo from S3:1320 StorePath: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestNARDeduplicationMetadataUploadBug531039756/001/store/baxqsiqy8b2429bvs777s923w90an468-file2.txt1321 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1322 Compression: zstd1323 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1324 NarSize: 1601325 References: 1326 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1327 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1328 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1329 {"version":1,"root":{"type":"regular","size":44}}13302026/10/25 19:01:17 INFO Vacuumed table table=objects13312026/10/25 19:01:17 INFO Aborted multipart uploads count=0 kept=013322026/10/25 19:01:18 WARN Force mode enabled - objects will be deleted immediately without grace period1333--- PASS: TestNARDeduplicationMetadataUploadBug (7.94s)1334=== CONT TestLeadEndsOnShutdown13352026/10/25 19:01:18 INFO Aborted multipart uploads count=0 kept=013362026/10/25 19:01:18 WARN Force mode enabled - objects will be deleted immediately without grace period13372026/10/25 19:01:18 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=013382026/10/25 19:01:18 INFO Vacuumed table table=pending_closures13392026/10/25 19:01:18 INFO Vacuumed table table=pending_objects13402026/10/25 19:01:18 INFO Vacuumed table table=multipart_uploads13412026/10/25 19:01:18 INFO Vacuumed table table=closures13422026/10/25 19:01:18 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=013432026/10/25 19:01:18 INFO Vacuumed table table=objects1344--- PASS: TestSweepSkipsRowsLockedByPush (7.24s)1345=== CONT TestLeadIncumbentAnnouncesAtOnce13462026/10/25 19:01:18 INFO Vacuumed table table=pending_closures13472026/10/25 19:01:18 INFO Vacuumed table table=pending_objects13482026/10/25 19:01:18 INFO Vacuumed table table=multipart_uploads13492026/10/25 19:01:18 INFO Vacuumed table table=closures13502026/10/25 19:01:18 INFO Vacuumed table table=objects1351--- PASS: TestSweepRechecksPendingAfterLocking (7.01s)1352=== CONT TestLeadElectsOneAndHandsOver13532026/10/25 19:01:18 INFO Aborted multipart uploads count=0 kept=013542026/10/25 19:01:18 WARN Force mode enabled - objects will be deleted immediately without grace period13552026/10/25 19:01:18 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=013562026/10/25 19:01:18 INFO Vacuumed table table=pending_closures13572026/10/25 19:01:18 INFO Vacuumed table table=pending_objects13582026/10/25 19:01:18 INFO Vacuumed table table=multipart_uploads13592026/10/25 19:01:18 INFO Received uploads request method=POST path=/api/pending_closures13602026/10/25 19:01:18 INFO Vacuumed table table=closures13612026/10/25 19:01:18 INFO Vacuumed table table=objects1362--- PASS: TestCommitRacingPendingCleanupKeepsObjects (7.12s)1363=== CONT TestConnectWaitsForAPeerMigration1364--- PASS: TestPushWaitsForSweepHoldingRow (7.44s)1365=== CONT TestResolveDBConnectionString1366=== RUN TestResolveDBConnectionString/flag_wins1367=== PAUSE TestResolveDBConnectionString/flag_wins1368=== RUN TestResolveDBConnectionString/file_when_flag_empty1369=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1370=== RUN TestResolveDBConnectionString/missing_file_is_an_error1371=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1372=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1373=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1374=== RUN TestResolveDBConnectionString/nothing_configured1375=== PAUSE TestResolveDBConnectionString/nothing_configured1376=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1377--- PASS: TestReadProxyConditionalGet (7.00s)1378=== CONT TestClientWithDependencies13792026/10/25 19:01:19 WARN readiness check failed error="closed pool"1380--- PASS: TestService_readinessHandler (6.74s)1381=== CONT TestClientMultipleUploads1382--- PASS: TestReadProxyHead (7.00s)1383=== CONT TestClientSharedPathCommittedMidPush1384--- PASS: TestReadProxyInvalidPath (7.02s)1385=== CONT TestClientErrorHandling1386=== RUN TestClientErrorHandling/InvalidStorePath1387=== PAUSE TestClientErrorHandling/InvalidStorePath1388=== RUN TestClientErrorHandling/InvalidAuthToken1389=== PAUSE TestClientErrorHandling/InvalidAuthToken1390=== RUN TestClientErrorHandling/ServerNotAvailable1391=== PAUSE TestClientErrorHandling/ServerNotAvailable1392=== CONT TestPinProtectsFromGC13932026/10/25 19:01:20 INFO Received uploads request method=POST path=/api/pending_closures1394--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.91s)1395=== CONT TestClientPushesUseOnePush1396=== NAME TestClientCADerivations1397 client_ca_test.go:136: Built CA derivation: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientCADerivations448061861/001/store/zxwa91fkd5pyfkyc6jhcqc9i8wzd9rri-ca-test13982026/10/25 19:01:21 INFO Aborted multipart uploads count=1 kept=013992026/10/25 19:01:21 INFO Received cleanup request method=DELETE path=/api/pending_closures14002026/10/25 19:01:21 INFO Aborted multipart uploads count=1 kept=01401--- PASS: TestPendingCleanupUsesOneCutoff (12.06s)1402=== CONT TestClientIntegration1403=== NAME TestClientCADerivations1404 client_ca_test.go:139: Found 1 dependencies (including self)14052026/10/25 19:01:21 INFO Received push request method=POST path=/api/pushes14062026/10/25 19:01:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14072026/10/25 19:01:21 INFO Uploading zxwa91fkd5pyfkyc6jhcqc9i8wzd9rri-ca-test (144B)14082026/10/25 19:01:21 WARN Failed to register uploaded object key=zxwa91fkd5pyfkyc6jhcqc9i8wzd9rri.ls error="server returned 404: 404 page not found\n"14092026/10/25 19:01:21 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14102026/10/25 19:01:21 WARN Failed to register uploaded object key=log/1080b55p5kh385rwj7kd6s6zwsd3qf8g-ca-test.drv error="server returned 404: 404 page not found\n"14112026/10/25 19:01:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14122026/10/25 19:01:21 INFO Signed narinfos id=1 count=114132026/10/25 19:01:21 INFO Uploading 1 narinfos14142026/10/25 19:01:21 INFO Received complete push request method=POST path=/api/pushes/1/complete14152026/10/25 19:01:21 WARN Failed to register uploaded object key=zxwa91fkd5pyfkyc6jhcqc9i8wzd9rri.narinfo error="server returned 404: 404 page not found\n"14162026/10/25 19:01:21 INFO Completed push id=1 objects=4 duration=61.379917ms14172026/10/25 19:01:21 INFO Upload complete. (322ms)1418 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientCADerivations448061861/001/store/zxwa91fkd5pyfkyc6jhcqc9i8wzd9rri-ca-test1419 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1420 Compression: zstd1421 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1422 NarSize: 1441423 References: 1424 Deriver: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientCADerivations448061861/001/store/1080b55p5kh385rwj7kd6s6zwsd3qf8g-ca-test.drv1425 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1426 client_ca_test.go:185: Checking for realisation files in S3...1427 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1428 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache14292026/10/25 19:01:21 INFO Aborted multipart uploads count=0 kept=014302026/10/25 19:01:21 WARN Force mode enabled - objects will be deleted immediately without grace period14312026/10/25 19:01:21 INFO Received uploads request method=POST path=/api/pending_closures1432 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket62?endpoint=http://localhost:54781®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientCADerivations448061861/001/store'1433 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11434--- PASS: TestTombstonedObjectOfferedWithoutWaiting (6.34s)1435=== CONT TestService_ReadAuthMiddleware1436--- PASS: TestClientCADerivations (8.58s)1437=== CONT TestService_AuthMiddleware_OIDC14382026/10/25 19:01:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55059/oidc14392026/10/25 19:01:22 INFO Received uploads request method=POST path=/api/pending_closures14402026/10/25 19:01:22 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=014412026/10/25 19:01:22 INFO Vacuumed table table=pending_closures14422026/10/25 19:01:22 INFO Vacuumed table table=pending_objects14432026/10/25 19:01:22 INFO Vacuumed table table=multipart_uploads14442026/10/25 19:01:22 INFO Vacuumed table table=closures14452026/10/25 19:01:22 INFO Vacuumed table table=objects1446--- PASS: TestGCSweepDeliversEachKeyOnce (7.51s)1447=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14482026/10/25 19:01:22 INFO Aborted multipart uploads count=0 kept=014492026/10/25 19:01:22 WARN Force mode enabled - objects will be deleted immediately without grace period14502026/10/25 19:01:22 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014512026/10/25 19:01:22 INFO Vacuumed table table=pending_closures14522026/10/25 19:01:22 INFO Vacuumed table table=pending_objects14532026/10/25 19:01:22 INFO Vacuumed table table=multipart_uploads14542026/10/25 19:01:22 INFO Vacuumed table table=closures14552026/10/25 19:01:22 INFO Vacuumed table table=objects1456--- PASS: TestGCSweepSkipsPendingObjects (6.48s)1457=== CONT TestService_RequireScope_OIDC14582026/10/25 19:01:22 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55065/oidc14592026/10/25 19:01:22 INFO Received uploads request method=POST path=/api/pending_closures14602026/10/25 19:01:22 INFO Received uploads request method=POST path=/api/pending_closures1461--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.27s)1462=== CONT TestCacheStatsHandler14632026/10/25 19:01:22 INFO Aborted multipart uploads count=0 kept=014642026/10/25 19:01:22 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=014652026/10/25 19:01:22 INFO Vacuumed table table=pending_closures14662026/10/25 19:01:22 INFO Vacuumed table table=pending_objects14672026/10/25 19:01:22 INFO Vacuumed table table=multipart_uploads14682026/10/25 19:01:22 INFO Vacuumed table table=closures14692026/10/25 19:01:22 INFO Vacuumed table table=objects14702026/10/25 19:01:22 INFO Aborted multipart uploads count=0 kept=014712026/10/25 19:01:22 WARN Force mode enabled - objects will be deleted immediately without grace period14722026/10/25 19:01:22 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014732026/10/25 19:01:22 INFO Vacuumed table table=pending_closures14742026/10/25 19:01:22 INFO Vacuumed table table=pending_objects14752026/10/25 19:01:22 INFO Vacuumed table table=multipart_uploads14762026/10/25 19:01:22 INFO Vacuumed table table=closures14772026/10/25 19:01:22 INFO Vacuumed table table=objects1478--- PASS: TestPushDedupSurvivesConcurrentGC (6.45s)1479=== CONT TestCacheConfigHandler1480=== RUN TestCacheConfigHandler/full_config,_no_issuer1481=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1482=== RUN TestCacheConfigHandler/no_cache_url_configured1483=== PAUSE TestCacheConfigHandler/no_cache_url_configured1484=== RUN TestCacheConfigHandler/no_signing_keys1485=== PAUSE TestCacheConfigHandler/no_signing_keys1486=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1487=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1488=== CONT TestService_AuthMiddleware_MTLSProxyHeader14892026/10/25 19:01:23 INFO Aborted multipart uploads count=0 kept=014902026/10/25 19:01:23 WARN Force mode enabled - objects will be deleted immediately without grace period14912026/10/25 19:01:23 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=014922026/10/25 19:01:23 INFO Vacuumed table table=pending_closures14932026/10/25 19:01:23 INFO Vacuumed table table=pending_objects14942026/10/25 19:01:23 INFO Vacuumed table table=multipart_uploads14952026/10/25 19:01:23 INFO Vacuumed table table=closures14962026/10/25 19:01:23 INFO Vacuumed table table=objects1497--- PASS: TestGCMetrics (6.40s)1498=== CONT TestService_ReadScope_PublicByDefault1499--- PASS: TestReadProxyOutlastsServerWriteTimeout (11.19s)1500=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale15012026/10/25 19:01:23 INFO Received uploads request method=POST path=/api/pending_closures15022026/10/25 19:01:23 INFO Received uploads request method=POST path=/api/pending_closures15032026/10/25 19:01:23 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15042026/10/25 19:01:23 INFO Uploading 2bpdg6qq675pq4n2nbp27nc6i06gm2rj-shared-dep (136B)15052026/10/25 19:01:23 INFO Uploading kkjgj45rgc18q93fasjw7lsiykdqnma3-a (256B)15062026/10/25 19:01:23 WARN Failed to register uploaded object key=2bpdg6qq675pq4n2nbp27nc6i06gm2rj.ls error="server returned 404: 404 page not found\n"15072026/10/25 19:01:23 WARN Failed to register uploaded object key=myvflw37nnq54c4q6xha0lqbsyysw668.ls error="server returned 404: 404 page not found\n"15082026/10/25 19:01:23 WARN Failed to register uploaded object key=nar/1xy4pk56ys43qgbkd91zjmlb08n8dagrk3lfknh310ib1d8w58cv.nar.zst error="server returned 404: 404 page not found\n"15092026/10/25 19:01:23 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15102026/10/25 19:01:23 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15112026/10/25 19:01:23 WARN Failed to register uploaded object key=kkjgj45rgc18q93fasjw7lsiykdqnma3.ls error="server returned 404: 404 page not found\n"15122026/10/25 19:01:23 INFO Signed narinfos id=1 count=215132026/10/25 19:01:23 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15142026/10/25 19:01:23 INFO Signed narinfos id=2 count=215152026/10/25 19:01:23 INFO Uploading 4 narinfos15162026/10/25 19:01:23 WARN Failed to register uploaded object key=myvflw37nnq54c4q6xha0lqbsyysw668.narinfo error="server returned 404: 404 page not found\n"15172026/10/25 19:01:23 WARN Failed to register uploaded object key=2bpdg6qq675pq4n2nbp27nc6i06gm2rj.narinfo error="server returned 404: 404 page not found\n"15182026/10/25 19:01:23 WARN Failed to register uploaded object key=kkjgj45rgc18q93fasjw7lsiykdqnma3.narinfo error="server returned 404: 404 page not found\n"15192026/10/25 19:01:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15202026/10/25 19:01:23 WARN Failed to register uploaded object key=2bpdg6qq675pq4n2nbp27nc6i06gm2rj.narinfo error="server returned 404: 404 page not found\n"15212026/10/25 19:01:23 INFO Completed upload id=1 objects=6 duration=26.129459ms15222026/10/25 19:01:23 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15232026/10/25 19:01:23 INFO Completed upload id=2 objects=6 duration=2.822666ms15242026/10/25 19:01:23 INFO Upload complete. (430ms)1525=== NAME TestClientFallsBackToClosures1526 client_pushes_test.go:112: Retrieved narinfo from S3:1527 StorePath: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientFallsBackToClosures2634665859/001/store/2bpdg6qq675pq4n2nbp27nc6i06gm2rj-shared-dep1528 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1529 Compression: zstd1530 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821531 NarSize: 1361532 References: 1533 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1534 client_pushes_test.go:112: Retrieved narinfo from S3:1535 StorePath: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientFallsBackToClosures2634665859/001/store/kkjgj45rgc18q93fasjw7lsiykdqnma3-a1536 URL: nar/1xy4pk56ys43qgbkd91zjmlb08n8dagrk3lfknh310ib1d8w58cv.nar.zst1537 Compression: zstd1538 NarHash: sha256:1xy4pk56ys43qgbkd91zjmlb08n8dagrk3lfknh310ib1d8w58cv1539 NarSize: 2561540 References: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientFallsBackToClosures2634665859/001/store/2bpdg6qq675pq4n2nbp27nc6i06gm2rj-shared-dep1541 CA: text:sha256:0lkbqk5s1ms1pyrdfjif3d6jbws1ckhrb3il4sy12jywq0ps17x61542 client_pushes_test.go:112: Retrieved narinfo from S3:1543 StorePath: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientFallsBackToClosures2634665859/001/store/myvflw37nnq54c4q6xha0lqbsyysw668-b1544 URL: nar/1xy4pk56ys43qgbkd91zjmlb08n8dagrk3lfknh310ib1d8w58cv.nar.zst1545 Compression: zstd1546 NarHash: sha256:1xy4pk56ys43qgbkd91zjmlb08n8dagrk3lfknh310ib1d8w58cv1547 NarSize: 2561548 References: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientFallsBackToClosures2634665859/001/store/2bpdg6qq675pq4n2nbp27nc6i06gm2rj-shared-dep1549 CA: text:sha256:0lkbqk5s1ms1pyrdfjif3d6jbws1ckhrb3il4sy12jywq0ps17x61550--- PASS: TestGCBugBareHashReferences (6.51s)1551=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh15522026/10/25 19:01:24 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld1 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1553--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (6.42s)1554=== CONT TestParseSingleRange/none1555=== CONT TestParseSingleRange/open-ended1556=== CONT TestParseSingleRange/closed1557--- PASS: TestClientFallsBackToClosures (7.48s)1558=== CONT TestParseSingleRange/malformed_both_empty1559=== CONT TestParseSingleRange/malformed_end_before_start1560=== CONT TestParseSingleRange/multi-range_ignored1561=== CONT TestParseSingleRange/malformed_no_dash1562=== CONT TestParseSingleRange/start_far_past_EOF1563=== CONT TestParseSingleRange/unknown_unit1564=== CONT TestParseSingleRange/start_past_EOF1565=== CONT TestParseSingleRange/suffix_exceeds_size1566=== CONT TestParseSingleRange/suffix1567=== CONT TestParseSingleRange/end_clamped_to_size1568=== CONT TestParseSingleRange/single_byte1569--- PASS: TestParseSingleRange (0.05s)1570 --- PASS: TestParseSingleRange/none (0.00s)1571 --- PASS: TestParseSingleRange/open-ended (0.00s)1572 --- PASS: TestParseSingleRange/closed (0.00s)1573 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1574 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1575 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1576 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1577 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1578 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1579 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1580 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1581 --- PASS: TestParseSingleRange/suffix (0.00s)1582 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1583 --- PASS: TestParseSingleRange/single_byte (0.00s)1584=== CONT TestPendingClosureWriteTimeout/empty1585=== CONT TestPendingClosureWriteTimeout/670k_objects1586=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1587=== CONT TestPendingClosureWriteTimeout/400_objects1588=== CONT TestProxyWriteTimeout/narinfo1589=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15902026/10/25 19:01:24 INFO Received uploads request method=POST path=/1591=== CONT TestProxyWriteTimeout/unknown_size1592=== CONT TestProxyWriteTimeout/10_GiB_nar1593=== CONT TestProxyWriteTimeout/1_GiB_nar1594--- PASS: TestProxyWriteTimeout (0.05s)1595 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1596 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1597 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1598 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1599=== CONT TestIsValidUploadKey/narinfo1600=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16012026/10/25 19:01:24 INFO Received request for more parts method=POST path=/1602=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16032026/10/25 19:01:24 INFO Received complete multipart upload request method=POST path=/1604=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16052026/10/25 19:01:24 INFO Received uploads request method=POST path=/1606--- PASS: TestUploadHandlersRejectInvalidKeys (0.05s)1607 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.01s)1608 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1609 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1610 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1611=== CONT TestIsValidCachePath/narinfo1612=== CONT TestIsValidUploadKey/unknown_type1613=== CONT TestIsValidUploadKey/empty_key1614=== CONT TestIsValidUploadKey/absolute1615=== CONT TestIsValidUploadKey/traversal_nar1616=== CONT TestIsValidUploadKey/traversal1617=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1618=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1619=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1620=== CONT TestIsValidUploadKey/index.html1621=== CONT TestIsValidUploadKey/nix-cache-info1622=== CONT TestIsValidUploadKey/realisation_plus_in_output1623=== CONT TestIsValidUploadKey/realisation1624=== CONT TestIsValidUploadKey/build_log_equals1625=== CONT TestIsValidUploadKey/build_log_question_mark1626=== CONT TestIsValidUploadKey/build_log_plus_in_name1627=== CONT TestIsValidUploadKey/build_log_home-manager_file1628=== CONT TestIsValidUploadKey/build_log1629=== CONT TestIsValidUploadKey/listing1630=== CONT TestIsValidUploadKey/nar_plain1631=== CONT TestIsValidUploadKey/nar_xz1632=== CONT TestIsValidCachePath/index.html1633=== CONT TestIsValidCachePath/nix-cache-info1634=== CONT TestIsValidCachePath/realisation1635=== CONT TestIsValidCachePath/log1636=== CONT TestIsValidCachePath/ls1637=== CONT TestIsValidCachePath/nar_uncompressed1638=== CONT TestIsValidCachePath/nar_bz21639=== CONT TestIsValidCachePath/nar_xz1640=== CONT TestIsValidCachePath/nar_zst1641=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1642=== CONT TestIsValidCachePath/leading_slash1643=== CONT TestIsValidUploadKey/nar_zst1644--- PASS: TestIsValidUploadKey (0.05s)1645 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1646 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1647 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1648 --- PASS: TestIsValidUploadKey/absolute (0.00s)1649 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1650 --- PASS: TestIsValidUploadKey/traversal (0.00s)1651 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1652 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1653 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1654 --- PASS: TestIsValidUploadKey/index.html (0.00s)1655 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1656 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1657 --- PASS: TestIsValidUploadKey/realisation (0.00s)1658 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1659 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1660 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1661 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1662 --- PASS: TestIsValidUploadKey/build_log (0.00s)1663 --- PASS: TestIsValidUploadKey/listing (0.00s)1664 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1665 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1666 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1667=== CONT TestIsValidCachePath/short_hash1668=== CONT TestIsValidCachePath/invalid_char_u1669=== CONT TestIsValidCachePath/empty1670=== CONT TestIsValidCachePath/random_path1671=== CONT TestIsValidCachePath/wrong_extension1672=== CONT TestIsValidCachePath/invalid_char_e1673=== CONT TestIsValidCachePath/traversal_in_middle1674=== CONT TestIsValidCachePath/traversal_parent1675--- PASS: TestIsValidCachePath (0.05s)1676 --- PASS: TestIsValidCachePath/narinfo (0.00s)1677 --- PASS: TestIsValidCachePath/index.html (0.00s)1678 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1679 --- PASS: TestIsValidCachePath/realisation (0.00s)1680 --- PASS: TestIsValidCachePath/log (0.00s)1681 --- PASS: TestIsValidCachePath/ls (0.00s)1682 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1683 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1684 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1685 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1686 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1687 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1688 --- PASS: TestIsValidCachePath/short_hash (0.00s)1689 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1690 --- PASS: TestIsValidCachePath/empty (0.00s)1691 --- PASS: TestIsValidCachePath/random_path (0.00s)1692 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1693 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1694 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1695 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1696=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16972026/10/25 19:01:24 INFO Received uploads request method=POST path=/16982026/10/25 19:01:24 INFO lead: acquired remote=192.0.2.1:12341699=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17002026/10/25 19:01:24 INFO Received request for more parts method=POST path=/1701=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17022026/10/25 19:01:24 INFO Received complete multipart upload request method=POST path=/1703--- PASS: TestUploadHandlersRejectOversizedBody (0.07s)1704 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)1705 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1706 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1707=== CONT TestPush_RejectsBadRequests/no_roots17082026/10/25 19:01:24 INFO Received push request method=POST path=/api/pushes1709=== CONT TestPush_RejectsBadRequests/bad_root17102026/10/25 19:01:24 INFO Received push request method=POST path=/api/pushes1711=== CONT TestPush_RejectsBadRequests/root_not_in_objects17122026/10/25 19:01:24 INFO Received push request method=POST path=/api/pushes1713=== CONT TestPush_RejectsBadRequests/no_objects17142026/10/25 19:01:24 INFO Received push request method=POST path=/api/pushes1715--- PASS: TestPush_RejectsBadRequests (6.67s)1716 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1717 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1718 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1719 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1720=== CONT TestServerTLSConfig/no_client_CA1721=== CONT TestServerTLSConfig/not_a_PEM_file1722=== CONT TestServerTLSConfig/missing_CA_file1723=== CONT TestGCEndsOnShutdown/before_the_run1724--- PASS: TestServerTLSConfig (0.01s)1725 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1726 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1727 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)17282026/10/25 19:01:24 INFO lead: acquired remote=192.0.2.1:123417292026/10/25 19:01:24 INFO lead: released remote=192.0.2.1:12341730--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.19s)1731=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17322026/10/25 19:01:24 INFO lead: acquired remote=192.0.2.1:123417332026/10/25 19:01:25 INFO lead: released remote=192.0.2.1:12341734--- PASS: TestLeadEndsOnShutdown (7.22s)1735=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1736=== NAME TestOrphanedObjectsGCStressTest1737 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1738 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1739--- PASS: TestDeleteClosuresRacingPins (11.78s)1740=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17412026/10/25 19:01:26 INFO lead: released remote=192.0.2.1:123417422026/10/25 19:01:26 INFO lead: acquired remote=192.0.2.1:12341743=== NAME TestClientWithDependencies1744 client_integration_test.go:613: Built derivation: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientWithDependencies3458787994/001/store/rw5anv2qichw5w6sfdrg0l18dc1sjb6p-test-script1745=== NAME TestClientMultipleUploads1746 client_integration_test.go:358: Created store path 0: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientMultipleUploads176310825/001/store/b442bp4y74pvk7fw0gpz68wfw0n8aq0z-test-file-0.txt1747=== NAME TestClientWithDependencies1748 client_integration_test.go:615: Found 1 dependencies (including self)1749--- PASS: TestConnectWaitsForAPeerMigration (7.59s)1750=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check17512026/10/25 19:01:26 INFO Received push request method=POST path=/api/pushes1752=== NAME TestClientMultipleUploads1753 client_integration_test.go:358: Created store path 1: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientMultipleUploads176310825/001/store/x9y7ad9yhh1lmj0d9yxxz2yjksmqa9s2-test-file-1.txt17542026/10/25 19:01:26 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17552026/10/25 19:01:26 INFO Uploading rw5anv2qichw5w6sfdrg0l18dc1sjb6p-test-script (136B)17562026/10/25 19:01:26 WARN Failed to register uploaded object key=rw5anv2qichw5w6sfdrg0l18dc1sjb6p.ls error="server returned 404: 404 page not found\n"17572026/10/25 19:01:26 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"17582026/10/25 19:01:26 WARN Failed to register uploaded object key=log/50zms42wqg5gjjlwpy4ypn710bggjl9q-test-script.drv error="server returned 404: 404 page not found\n"17592026/10/25 19:01:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17602026/10/25 19:01:26 INFO Signed narinfos id=1 count=117612026/10/25 19:01:26 INFO Uploading 1 narinfos17622026/10/25 19:01:26 INFO Received complete push request method=POST path=/api/pushes/1/complete17632026/10/25 19:01:26 WARN Failed to register uploaded object key=rw5anv2qichw5w6sfdrg0l18dc1sjb6p.narinfo error="server returned 404: 404 page not found\n"1764 client_integration_test.go:358: Created store path 2: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientMultipleUploads176310825/001/store/263vd0wff5dkmlvilhdp973agf4n3ssa-test-file-2.txt17652026/10/25 19:01:26 INFO Completed push id=1 objects=4 duration=42.673125ms17662026/10/25 19:01:26 INFO Upload complete. (338ms)1767=== NAME TestClientWithDependencies1768 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientWithDependencies3458787994/001/store) requires matching store prefix17692026/10/25 19:01:26 INFO Received push request method=POST path=/api/pushes17702026/10/25 19:01:26 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17712026/10/25 19:01:26 INFO Uploading 263vd0wff5dkmlvilhdp973agf4n3ssa-test-file-2.txt (160B)17722026/10/25 19:01:26 INFO Uploading b442bp4y74pvk7fw0gpz68wfw0n8aq0z-test-file-0.txt (160B)17732026/10/25 19:01:26 INFO Uploading x9y7ad9yhh1lmj0d9yxxz2yjksmqa9s2-test-file-1.txt (160B)1774--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (7.46s)1775=== CONT TestResolveDBConnectionString/flag_wins1776=== CONT TestResolveDBConnectionString/nothing_configured1777--- PASS: TestClientWithDependencies (7.40s)1778=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1779=== CONT TestResolveDBConnectionString/missing_file_is_an_error1780=== CONT TestResolveDBConnectionString/file_when_flag_empty1781=== CONT TestClientErrorHandling/InvalidStorePath1782=== CONT TestClientErrorHandling/ServerNotAvailable1783--- PASS: TestResolveDBConnectionString (0.07s)1784 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1785 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1786 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1787 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1788 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)17892026/10/25 19:01:26 WARN Failed to register uploaded object key=263vd0wff5dkmlvilhdp973agf4n3ssa.ls error="server returned 404: 404 page not found\n"17902026/10/25 19:01:26 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17912026/10/25 19:01:26 WARN Failed to register uploaded object key=b442bp4y74pvk7fw0gpz68wfw0n8aq0z.ls error="server returned 404: 404 page not found\n"17922026/10/25 19:01:26 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17932026/10/25 19:01:26 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17942026/10/25 19:01:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17952026/10/25 19:01:26 WARN Failed to register uploaded object key=x9y7ad9yhh1lmj0d9yxxz2yjksmqa9s2.ls error="server returned 404: 404 page not found\n"17962026/10/25 19:01:26 INFO Signed narinfos id=1 count=317972026/10/25 19:01:26 INFO Uploading 3 narinfos17982026/10/25 19:01:27 WARN Failed to register uploaded object key=x9y7ad9yhh1lmj0d9yxxz2yjksmqa9s2.narinfo error="server returned 404: 404 page not found\n"17992026/10/25 19:01:27 INFO Received complete push request method=POST path=/api/pushes/1/complete18002026/10/25 19:01:27 WARN Failed to register uploaded object key=b442bp4y74pvk7fw0gpz68wfw0n8aq0z.narinfo error="server returned 404: 404 page not found\n"18012026/10/25 19:01:27 WARN Failed to register uploaded object key=263vd0wff5dkmlvilhdp973agf4n3ssa.narinfo error="server returned 404: 404 page not found\n"18022026/10/25 19:01:27 INFO Completed push id=1 objects=9 duration=37.682875ms18032026/10/25 19:01:27 INFO Upload complete. (417ms)1804=== NAME TestClientMultipleUploads1805 client_integration_test.go:369: Uploaded 3 paths in 456.135125ms18062026/10/25 19:01:27 INFO Received push request method=POST path=/api/pushes18072026/10/25 19:01:27 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)18082026/10/25 19:01:27 INFO Uploading g123x23j4ynkf31mb7isy6b63fc85a9r-top (264B)18092026/10/25 19:01:27 INFO Uploading 4plj0y3xfcks4n7addpkkn7qihmdi3kv-shared-dep (136B)18102026/10/25 19:01:27 INFO lead: released remote=192.0.2.1:12341811--- PASS: TestLeadElectsOneAndHandsOver (8.83s)1812=== CONT TestClientErrorHandling/InvalidAuthToken1813=== CONT TestCacheConfigHandler/full_config,_no_issuer1814--- PASS: TestClientMultipleUploads (7.64s)1815=== CONT TestCacheConfigHandler/no_signing_keys18162026/10/25 19:01:27 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1817=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1818=== CONT TestCacheConfigHandler/no_cache_url_configured1819--- PASS: TestCacheConfigHandler (0.02s)1820 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1821 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1822 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1823 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)18242026/10/25 19:01:27 WARN Failed to register uploaded object key=nar/18nsqxfvgp7x064hsdjdb1lx037pll0vv78yc7fj4nq7za8rmxz3.nar.zst error="server returned 404: 404 page not found\n"18252026/10/25 19:01:27 WARN Failed to register uploaded object key=g123x23j4ynkf31mb7isy6b63fc85a9r.ls error="server returned 404: 404 page not found\n"18262026/10/25 19:01:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18272026/10/25 19:01:27 WARN Failed to register uploaded object key=4plj0y3xfcks4n7addpkkn7qihmdi3kv.ls error="server returned 404: 404 page not found\n"18282026/10/25 19:01:27 INFO Signed narinfos id=1 count=218292026/10/25 19:01:27 INFO Uploading 2 narinfos18302026/10/25 19:01:27 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18312026/10/25 19:01:27 WARN Failed to register uploaded object key=g123x23j4ynkf31mb7isy6b63fc85a9r.narinfo error="server returned 404: 404 page not found\n"18322026/10/25 19:01:27 WARN Failed to register uploaded object key=4plj0y3xfcks4n7addpkkn7qihmdi3kv.narinfo error="server returned 404: 404 page not found\n"18332026/10/25 19:01:27 INFO Received complete push request method=POST path=/api/pushes/1/complete18342026/10/25 19:01:27 INFO Completed push id=1 objects=6 duration=16.90025ms18352026/10/25 19:01:27 INFO Upload complete. (391ms)1836=== NAME TestClientSharedPathCommittedMidPush1837 client_integration_test.go:680: Retrieved narinfo from S3:1838 StorePath: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientSharedPathCommittedMidPush1124780327/001/store/4plj0y3xfcks4n7addpkkn7qihmdi3kv-shared-dep1839 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1840 Compression: zstd1841 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821842 NarSize: 1361843 References: 1844 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1845 client_integration_test.go:680: Retrieved narinfo from S3:1846 StorePath: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientSharedPathCommittedMidPush1124780327/001/store/g123x23j4ynkf31mb7isy6b63fc85a9r-top1847 URL: nar/18nsqxfvgp7x064hsdjdb1lx037pll0vv78yc7fj4nq7za8rmxz3.nar.zst1848 Compression: zstd1849 NarHash: sha256:18nsqxfvgp7x064hsdjdb1lx037pll0vv78yc7fj4nq7za8rmxz31850 NarSize: 2641851 References: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientSharedPathCommittedMidPush1124780327/001/store/4plj0y3xfcks4n7addpkkn7qihmdi3kv-shared-dep1852 CA: text:sha256:1hzql7h264r89c614pwri5g6yac3h8qrq6qydsfv17szv4gwpvg11853=== NAME TestPinProtectsFromGC1854 client_integration_test.go:731: Pinned store path: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestPinProtectsFromGC3639463503/001/store/qvsgdyip15r0ba9y8z6wfq1q569f9mcx-pinned-file.txt1855 client_integration_test.go:732: Unpinned store path: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestPinProtectsFromGC3639463503/001/store/869y90amm6azs5xb1rzfi11a0kzwg104-unpinned-file.txt18562026/10/25 19:01:27 WARN Request failed, retrying attempt=2 backoff=186.651992ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1857--- PASS: TestClientSharedPathCommittedMidPush (7.58s)18582026/10/25 19:01:27 INFO Received push request method=POST path=/api/pushes18592026/10/25 19:01:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18602026/10/25 19:01:27 INFO Uploading qvsgdyip15r0ba9y8z6wfq1q569f9mcx-pinned-file.txt (128B)18612026/10/25 19:01:27 WARN Request failed, retrying attempt=3 backoff=396.56243ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18622026/10/25 19:01:27 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"18632026/10/25 19:01:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18642026/10/25 19:01:27 WARN Failed to register uploaded object key=qvsgdyip15r0ba9y8z6wfq1q569f9mcx.ls error="server returned 404: 404 page not found\n"18652026/10/25 19:01:27 INFO Signed narinfos id=1 count=118662026/10/25 19:01:27 INFO Uploading 1 narinfos18672026/10/25 19:01:27 INFO Received complete push request method=POST path=/api/pushes/1/complete18682026/10/25 19:01:27 WARN Failed to register uploaded object key=qvsgdyip15r0ba9y8z6wfq1q569f9mcx.narinfo error="server returned 404: 404 page not found\n"18692026/10/25 19:01:27 INFO Completed push id=1 objects=3 duration=23.147458ms18702026/10/25 19:01:27 INFO Upload complete. (271ms)18712026/10/25 19:01:27 INFO Received push request method=POST path=/api/pushes18722026/10/25 19:01:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18732026/10/25 19:01:27 INFO Uploading 869y90amm6azs5xb1rzfi11a0kzwg104-unpinned-file.txt (128B)18742026/10/25 19:01:27 WARN Failed to register uploaded object key=869y90amm6azs5xb1rzfi11a0kzwg104.ls error="server returned 404: 404 page not found\n"18752026/10/25 19:01:27 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18762026/10/25 19:01:27 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18772026/10/25 19:01:27 INFO Signed narinfos id=2 count=118782026/10/25 19:01:27 INFO Uploading 1 narinfos18792026/10/25 19:01:28 INFO Received complete push request method=POST path=/api/pushes/2/complete18802026/10/25 19:01:28 WARN Failed to register uploaded object key=869y90amm6azs5xb1rzfi11a0kzwg104.narinfo error="server returned 404: 404 page not found\n"18812026/10/25 19:01:28 INFO Completed push id=2 objects=3 duration=877.959µs18822026/10/25 19:01:28 INFO Upload complete. (223ms)18832026/10/25 19:01:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures18842026/10/25 19:01:28 INFO Garbage collection started18852026/10/25 19:01:28 WARN Request failed, retrying attempt=4 backoff=733.982943ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18862026/10/25 19:01:28 INFO Received push request method=POST path=/api/pushes18872026/10/25 19:01:28 INFO Aborted multipart uploads count=0 kept=01888--- PASS: TestService_ReadAuthMiddleware (6.39s)18892026/10/25 19:01:28 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18902026/10/25 19:01:28 INFO Uploading hq0qrw1j5kyrfavv3ig78air4z24z88i-b (256B)18912026/10/25 19:01:28 INFO Uploading 6zmn1hqxwfbnp9d43l2qs086jp50g5pk-shared-dep (136B)18922026/10/25 19:01:28 WARN Force mode enabled - objects will be deleted immediately without grace period1893=== NAME TestClientIntegration1894 client_integration_test.go:286: Created store path: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientIntegration4243553150/002/store/mmbi49s8g6wwin3k3349qzi2c50w9rc9-test-file.txt18952026/10/25 19:01:28 WARN Failed to register uploaded object key=26l7pzq6c0c6dzawqs4bzgcxnpykxzbk.ls error="server returned 404: 404 page not found\n"18962026/10/25 19:01:28 WARN Failed to register uploaded object key=hq0qrw1j5kyrfavv3ig78air4z24z88i.ls error="server returned 404: 404 page not found\n"18972026/10/25 19:01:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18982026/10/25 19:01:28 WARN Failed to register uploaded object key=nar/1m7639dwyvbz61p9f5kkcz38b2qzml9dhx3vlhgwkwzj7a7mgyk7.nar.zst error="server returned 404: 404 page not found\n"18992026/10/25 19:01:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19002026/10/25 19:01:28 WARN Failed to register uploaded object key=6zmn1hqxwfbnp9d43l2qs086jp50g5pk.ls error="server returned 404: 404 page not found\n"19012026/10/25 19:01:28 INFO Signed narinfos id=1 count=319022026/10/25 19:01:28 INFO Uploading 3 narinfos19032026/10/25 19:01:28 WARN Failed to register uploaded object key=6zmn1hqxwfbnp9d43l2qs086jp50g5pk.narinfo error="server returned 404: 404 page not found\n"19042026/10/25 19:01:28 WARN Failed to register uploaded object key=26l7pzq6c0c6dzawqs4bzgcxnpykxzbk.narinfo error="server returned 404: 404 page not found\n"19052026/10/25 19:01:28 INFO Received push request method=POST path=/api/pushes19062026/10/25 19:01:28 INFO Received complete push request method=POST path=/api/pushes/1/complete19072026/10/25 19:01:28 WARN Failed to register uploaded object key=hq0qrw1j5kyrfavv3ig78air4z24z88i.narinfo error="server returned 404: 404 page not found\n"19082026/10/25 19:01:28 INFO Completed push id=1 objects=8 duration=32.401834ms19092026/10/25 19:01:28 INFO Upload complete. (381ms)19102026/10/25 19:01:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1911=== NAME TestClientPushesUseOnePush1912 client_pushes_test.go:97: Retrieved narinfo from S3:1913 StorePath: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientPushesUseOnePush2601842054/001/store/6zmn1hqxwfbnp9d43l2qs086jp50g5pk-shared-dep1914 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1915 Compression: zstd1916 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821917 NarSize: 1361918 References: 1919 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n19202026/10/25 19:01:28 INFO Uploading mmbi49s8g6wwin3k3349qzi2c50w9rc9-test-file.txt (152B)1921 client_pushes_test.go:97: Retrieved narinfo from S3:1922 StorePath: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientPushesUseOnePush2601842054/001/store/26l7pzq6c0c6dzawqs4bzgcxnpykxzbk-a1923 URL: nar/1m7639dwyvbz61p9f5kkcz38b2qzml9dhx3vlhgwkwzj7a7mgyk7.nar.zst1924 Compression: zstd1925 NarHash: sha256:1m7639dwyvbz61p9f5kkcz38b2qzml9dhx3vlhgwkwzj7a7mgyk71926 NarSize: 2561927 References: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientPushesUseOnePush2601842054/001/store/6zmn1hqxwfbnp9d43l2qs086jp50g5pk-shared-dep1928 CA: text:sha256:1hwy3pxms42qn6dkyscxk7v5d0qnr3bxfjhvxmxs66fqsbz6dyjw1929 client_pushes_test.go:97: Retrieved narinfo from S3:1930 StorePath: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientPushesUseOnePush2601842054/001/store/hq0qrw1j5kyrfavv3ig78air4z24z88i-b1931 URL: nar/1m7639dwyvbz61p9f5kkcz38b2qzml9dhx3vlhgwkwzj7a7mgyk7.nar.zst1932 Compression: zstd1933 NarHash: sha256:1m7639dwyvbz61p9f5kkcz38b2qzml9dhx3vlhgwkwzj7a7mgyk71934 NarSize: 2561935 References: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientPushesUseOnePush2601842054/001/store/6zmn1hqxwfbnp9d43l2qs086jp50g5pk-shared-dep1936 CA: text:sha256:1hwy3pxms42qn6dkyscxk7v5d0qnr3bxfjhvxmxs66fqsbz6dyjw19372026/10/25 19:01:28 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19382026/10/25 19:01:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19392026/10/25 19:01:28 WARN Failed to register uploaded object key=mmbi49s8g6wwin3k3349qzi2c50w9rc9.ls error="server returned 404: 404 page not found\n"19402026/10/25 19:01:28 INFO Signed narinfos id=1 count=119412026/10/25 19:01:28 INFO Uploading 1 narinfos19422026/10/25 19:01:28 INFO Received complete push request method=POST path=/api/pushes/1/complete1943=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token19442026/10/25 19:01:28 WARN Failed to register uploaded object key=mmbi49s8g6wwin3k3349qzi2c50w9rc9.narinfo error="server returned 404: 404 page not found\n"1945=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1946=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1947=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1948=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1949=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1950=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1951=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1952=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token19532026/10/25 19:01:28 INFO Completed push id=1 objects=3 duration=54.720417ms1954=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19552026/10/25 19:01:28 INFO Upload complete. (442ms)19562026/10/25 19:01:28 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]1957=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1958=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1959--- PASS: TestClientPushesUseOnePush (7.61s)19602026/10/25 19:01:28 WARN Authentication failed token_preview=eyJhbGciOi...fM6Vu_vcPw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1961--- PASS: TestService_AuthMiddleware_OIDC (6.84s)1962 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1963 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1964 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1965 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)19662026/10/25 19:01:28 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=019672026/10/25 19:01:28 INFO All 1 paths already cached1968=== NAME TestClientIntegration1969 client_integration_test.go:312: Retrieved narinfo from S3:1970 StorePath: /private/var/tb/1/scratch/b566a4a9a208906d/build/TestClientIntegration4243553150/002/store/mmbi49s8g6wwin3k3349qzi2c50w9rc9-test-file.txt1971 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1972 Compression: zstd1973 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11974 NarSize: 1521975 References: 1976 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11977 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1978 client_integration_test.go:313: Decompressed .ls content (64 bytes):1979 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1980 client_integration_test.go:316: Testing garbage collection...19812026/10/25 19:01:28 INFO Vacuumed table table=pending_closures19822026/10/25 19:01:28 INFO Vacuumed table table=pending_objects19832026/10/25 19:01:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures19842026/10/25 19:01:28 INFO Garbage collection started19852026/10/25 19:01:28 INFO Vacuumed table table=multipart_uploads19862026/10/25 19:01:28 WARN Request failed, retrying attempt=5 backoff=1.487751108s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19872026/10/25 19:01:28 INFO Aborted multipart uploads count=0 kept=019882026/10/25 19:01:28 WARN Force mode enabled - objects will be deleted immediately without grace period19892026/10/25 19:01:28 INFO Vacuumed table table=closures19902026/10/25 19:01:28 INFO Vacuumed table table=objects19912026/10/25 19:01:28 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19922026/10/25 19:01:28 WARN mTLS auth: bound subjects configured but subject DN unavailable19932026/10/25 19:01:28 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1994--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.78s)19952026/10/25 19:01:29 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=019962026/10/25 19:01:29 INFO Vacuumed table table=pending_closures1997=== RUN TestService_RequireScope_OIDC/builder_may_write1998=== PAUSE TestService_RequireScope_OIDC/builder_may_write1999=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2000=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2001=== RUN TestService_RequireScope_OIDC/ops_may_admin2002=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2003=== RUN TestService_RequireScope_OIDC/ops_may_not_write2004=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2005=== RUN TestService_RequireScope_OIDC/reader_may_not_write2006=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2007=== RUN TestService_RequireScope_OIDC/static_token_may_admin2008=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2009=== RUN TestService_RequireScope_OIDC/static_token_may_write2010=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2011=== RUN TestService_RequireScope_OIDC/reader_may_read2012=== PAUSE TestService_RequireScope_OIDC/reader_may_read2013=== RUN TestService_RequireScope_OIDC/writer_implies_read2014=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2015=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2016=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2017=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc2018=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc20192026/10/25 19:01:29 INFO Vacuumed table table=pending_objects2020=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2021=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2022=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2023=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2024=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2025=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2026=== CONT TestService_RequireScope_OIDC/builder_may_write2027=== CONT TestService_RequireScope_OIDC/reader_may_read20282026/10/25 19:01:29 INFO Vacuumed table table=multipart_uploads2029=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2030=== CONT TestService_RequireScope_OIDC/ops_may_not_write2031=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2032=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2033=== CONT TestService_RequireScope_OIDC/reader_may_not_write20342026/10/25 19:01:29 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]2035=== CONT TestService_RequireScope_OIDC/static_token_may_write2036=== CONT TestService_RequireScope_OIDC/static_token_may_admin2037=== CONT TestService_RequireScope_OIDC/ops_may_admin2038=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2039=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2040=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2041=== CONT TestService_RequireScope_OIDC/writer_implies_read2042--- PASS: TestService_RequireScope_OIDC (7.18s)2043 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2044 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2045 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2046 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2047 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2048 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2049 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2050 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2051 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2052 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2053 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2054 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2055 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2056 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)20572026/10/25 19:01:29 INFO Vacuumed table table=closures20582026/10/25 19:01:29 INFO Vacuumed table table=objects2059--- PASS: TestCacheStatsHandler (7.24s)20602026/10/25 19:01:30 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020612026/10/25 19:01:30 INFO Received create pin request method=POST path=/api/pins/myapp20622026/10/25 19:01:30 INFO Created/updated pin name=myapp store_path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestPinProtectsFromGC3639463503/001/store/qvsgdyip15r0ba9y8z6wfq1q569f9mcx-pinned-file.txt narinfo_key=qvsgdyip15r0ba9y8z6wfq1q569f9mcx.narinfo20632026/10/25 19:01:30 INFO Starting cleanup of old closures method=DELETE path=/api/closures20642026/10/25 19:01:30 INFO Garbage collection started20652026/10/25 19:01:30 INFO Aborted multipart uploads count=0 kept=020662026/10/25 19:01:30 WARN Force mode enabled - objects will be deleted immediately without grace period20672026/10/25 19:01:30 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020682026/10/25 19:01:30 INFO Vacuumed table table=pending_closures20692026/10/25 19:01:30 INFO Vacuumed table table=pending_objects20702026/10/25 19:01:30 INFO Vacuumed table table=multipart_uploads20712026/10/25 19:01:30 INFO Vacuumed table table=closures2072--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (7.32s)20732026/10/25 19:01:30 INFO Vacuumed table table=objects20742026/10/25 19:01:30 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20752026/10/25 19:01:30 WARN Request failed, retrying attempt=2 backoff=183.164526ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2076--- PASS: TestService_ReadScope_PublicByDefault (7.22s)20772026/10/25 19:01:30 WARN Request failed, retrying attempt=3 backoff=427.61115ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20782026/10/25 19:01:30 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02079=== NAME TestClientIntegration2080 client_integration_test.go:323: Objects in database after GC:2081 client_integration_test.go:323: Successfully deleted all objects with GC --force2082--- PASS: TestClientIntegration (9.77s)20832026/10/25 19:01:31 WARN Request failed, retrying attempt=4 backoff=802.554984ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20842026/10/25 19:01:31 INFO Received uploads request method=POST path=/api/pending_closures2085--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2086 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (8.03s)2087 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (7.73s)20882026/10/25 19:01:31 INFO Aborted multipart uploads count=0 kept=020892026/10/25 19:01:31 WARN Force mode enabled - objects will be deleted immediately without grace period20902026-10-25 19:01:31.803 UTC [18595] ERROR: canceling statement due to user request20912026-10-25 19:01:31.803 UTC [18595] STATEMENT: -- name: MarkStaleObjects :execrows2092 WITH RECURSIVE ct AS (2093 SELECT timezone('UTC', now()) AS now2094 ),2095 closure_reach AS (2096 -- Start with all closure keys2097 SELECT o.key, o.refs2098 FROM objects o2099 INNER JOIN closures c ON o.key = c.key2100 UNION2101 -- Recursively add all referenced objects2102 SELECT o.key, o.refs2103 FROM objects o2104 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2105 ),2106 reachable_objects AS (2107 SELECT DISTINCT key FROM closure_reach2108 ),2109 stale_objects AS (2110 SELECT o.key2111 FROM objects AS o, ct2112 WHERE2113 NOT EXISTS (2114 SELECT 12115 FROM reachable_objects ro2116 WHERE ro.key = o.key2117 )2118 AND NOT EXISTS (2119 SELECT 12120 FROM pending_objects AS po2121 WHERE po.key = o.key2122 )2123 AND o.deleted_at IS NULL -- Only mark fresh objects2124 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2125 FOR UPDATE2126 )2127 UPDATE objects2128 SET2129 deleted_at = ct.now,2130 first_deleted_at = COALESCE(first_deleted_at, ct.now)2131 FROM stale_objects, ct2132 WHERE objects.key = stale_objects.key2133 21342026/10/25 19:01:31 WARN Request failed, retrying attempt=5 backoff=1.610065183s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21352026/10/25 19:01:31 INFO Aborted multipart uploads count=0 kept=021362026/10/25 19:01:31 WARN Force mode enabled - objects will be deleted immediately without grace period21372026/10/25 19:01:32 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:54781/bucket96/?delete=\": context canceled"2138--- PASS: TestGCEndsOnShutdown (0.00s)2139 --- PASS: TestGCEndsOnShutdown/before_the_run (7.11s)2140 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (7.26s)2141 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (6.69s)2142--- PASS: TestPendingClosureWriteTimeout (0.05s)2143 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2144 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2145 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2146 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (8.09s)21472026/10/25 19:01:32 INFO Received uploads request method=POST path=/api/pending_closures2148=== NAME TestPinProtectsFromGC2149 client_integration_test.go:840: Pin successfully protected closure from garbage collection21502026/10/25 19:01:32 INFO Aborted multipart uploads count=0 kept=021512026/10/25 19:01:32 WARN Force mode enabled - objects will be deleted immediately without grace period2152--- PASS: TestPinProtectsFromGC (12.05s)21532026/10/25 19:01:32 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=021542026/10/25 19:01:32 INFO Vacuumed table table=pending_closures21552026/10/25 19:01:32 INFO Vacuumed table table=pending_objects21562026/10/25 19:01:32 INFO Vacuumed table table=multipart_uploads21572026/10/25 19:01:32 INFO Vacuumed table table=closures21582026/10/25 19:01:32 INFO Received uploads request method=POST path=/api/pending_closures21592026/10/25 19:01:32 INFO Vacuumed table table=objects21602026/10/25 19:01:32 INFO Aborted multipart uploads count=0 kept=021612026/10/25 19:01:32 WARN Force mode enabled - objects will be deleted immediately without grace period21622026/10/25 19:01:32 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=021632026/10/25 19:01:32 INFO Vacuumed table table=pending_closures21642026/10/25 19:01:32 INFO Vacuumed table table=pending_objects21652026/10/25 19:01:32 INFO Vacuumed table table=multipart_uploads21662026/10/25 19:01:32 INFO Vacuumed table table=closures21672026/10/25 19:01:32 INFO Vacuumed table table=objects2168--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2169 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (6.75s)2170 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (6.27s)21712026/10/25 19:01:33 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21722026/10/25 19:01:33 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21732026/10/25 19:01:33 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"21742026/10/25 19:01:33 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21752026/10/25 19:01:33 WARN Request failed, retrying attempt=2 backoff=211.377476ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21762026/10/25 19:01:33 WARN Request failed, retrying attempt=3 backoff=387.663615ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21772026/10/25 19:01:34 WARN Request failed, retrying attempt=4 backoff=878.847817ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21782026/10/25 19:01:35 WARN Request failed, retrying attempt=5 backoff=1.477114933s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21792026/10/25 19:01:36 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21802026/10/25 19:01:36 WARN Request failed, retrying attempt=2 backoff=207.482491ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21812026/10/25 19:01:36 WARN Request failed, retrying attempt=3 backoff=373.435492ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21822026/10/25 19:01:37 WARN Request failed, retrying attempt=4 backoff=770.637397ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21832026/10/25 19:01:38 WARN Request failed, retrying attempt=5 backoff=1.452603369s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2184--- PASS: TestClientErrorHandling (0.01s)2185 --- PASS: TestClientErrorHandling/InvalidStorePath (5.95s)2186 --- PASS: TestClientErrorHandling/InvalidAuthToken (5.89s)2187 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.93s)2188=== NAME TestOrphanedObjectsGCStressTest2189 orphaned_objects_gc_test.go:503: Stress test completed successfully:2190 orphaned_objects_gc_test.go:504: - Active objects preserved: 202191 orphaned_objects_gc_test.go:505: - Objects deleted: 2102192 orphaned_objects_gc_test.go:506: - Total GC'd: 2102193--- PASS: TestOrphanedObjectsGCStressTest (33.17s)2194PASS21952026-10-25 19:01:40.627 UTC [18144] LOG: received smart shutdown request21962026-10-25 19:01:40.628 UTC [18144] LOG: background worker "logical replication launcher" (PID 18154) exited with exit code 121972026-10-25 19:01:40.635 UTC [18149] LOG: shutting down21982026-10-25 19:01:40.635 UTC [18149] LOG: checkpoint starting: shutdown immediate21992026-10-25 19:01:41.925 UTC [18149] LOG: checkpoint complete: wrote 12151 buffers (74.2%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 31 recycled; write=0.590 s, sync=0.658 s, total=1.291 s; sync files=34045, longest=0.001 s, average=0.001 s; distance=502120 kB, estimate=502120 kB; lsn=0/201E7348, redo lsn=0/201E734822002026-10-25 19:01:41.932 UTC [18144] LOG: database system is shut down2201Running OIDC tests...2202=== RUN TestAudienceForIssuer2203=== PAUSE TestAudienceForIssuer2204=== RUN TestGlobMatch2205=== PAUSE TestGlobMatch2206=== RUN TestValidateToken_ValidToken2207=== PAUSE TestValidateToken_ValidToken2208=== RUN TestValidateToken_WrongAudience2209=== PAUSE TestValidateToken_WrongAudience2210=== RUN TestValidateToken_Expired2211=== PAUSE TestValidateToken_Expired2212=== RUN TestValidateToken_BoundClaimsMismatch2213=== PAUSE TestValidateToken_BoundClaimsMismatch2214=== RUN TestValidateToken_BoundSubjectMismatch2215=== PAUSE TestValidateToken_BoundSubjectMismatch2216=== RUN TestValidateToken_MultipleProviders2217=== PAUSE TestValidateToken_MultipleProviders2218=== RUN TestValidateToken_NoMatchingProvider2219=== PAUSE TestValidateToken_NoMatchingProvider2220=== RUN TestValidateToken_KubernetesServiceAccount2221=== PAUSE TestValidateToken_KubernetesServiceAccount2222=== RUN TestNewValidator_KubernetesRequiresCA2223=== PAUSE TestNewValidator_KubernetesRequiresCA2224=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2225=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2226=== RUN TestPins_ReservedForMatchingRule2227=== PAUSE TestPins_ReservedForMatchingRule2228=== RUN TestPins_TopLevelShorthand2229=== PAUSE TestPins_TopLevelShorthand2230=== RUN TestPins_ConfigValidation2231=== PAUSE TestPins_ConfigValidation2232=== RUN TestScopes_LegacyProviderDefaultsToWrite2233=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2234=== RUN TestScopes_Rules2235=== PAUSE TestScopes_Rules2236=== RUN TestScopes_ConfigValidation2237=== PAUSE TestScopes_ConfigValidation2238=== CONT TestAudienceForIssuer2239--- PASS: TestAudienceForIssuer (0.00s)2240=== CONT TestValidateToken_NoMatchingProvider2241=== CONT TestScopes_ConfigValidation2242=== CONT TestPins_ReservedForMatchingRule2243=== CONT TestValidateToken_MultipleProviders2244=== CONT TestValidateToken_BoundSubjectMismatch2245=== CONT TestValidateToken_BoundClaimsMismatch2246=== CONT TestValidateToken_Expired2247=== CONT TestValidateToken_WrongAudience2248--- PASS: TestScopes_ConfigValidation (0.01s)2249=== CONT TestGlobMatch2250=== RUN TestGlobMatch/foo_foo2251=== PAUSE TestGlobMatch/foo_foo2252=== RUN TestGlobMatch/foo_bar2253=== PAUSE TestGlobMatch/foo_bar2254=== RUN TestGlobMatch/*_2255=== PAUSE TestGlobMatch/*_2256=== RUN TestGlobMatch/*_anything2257=== PAUSE TestGlobMatch/*_anything2258=== RUN TestGlobMatch/foo*_foo2259=== PAUSE TestGlobMatch/foo*_foo2260=== CONT TestNewValidator_KubernetesRequiresCA2261=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2262=== CONT TestPins_ConfigValidation2263=== CONT TestScopes_LegacyProviderDefaultsToWrite2264=== CONT TestScopes_Rules2265=== CONT TestPins_TopLevelShorthand2266=== CONT TestValidateToken_KubernetesServiceAccount2267=== CONT TestValidateToken_ValidToken2268--- PASS: TestPins_ConfigValidation (0.01s)2269=== RUN TestGlobMatch/foo*_foobar2270=== PAUSE TestGlobMatch/foo*_foobar2271=== RUN TestGlobMatch/foo*_bar2272=== PAUSE TestGlobMatch/foo*_bar2273=== RUN TestGlobMatch/*bar_bar2274=== PAUSE TestGlobMatch/*bar_bar2275=== RUN TestGlobMatch/*bar_foobar2276=== PAUSE TestGlobMatch/*bar_foobar2277=== RUN TestGlobMatch/*bar_foo2278=== PAUSE TestGlobMatch/*bar_foo2279=== RUN TestGlobMatch/foo*bar_foobar2280=== PAUSE TestGlobMatch/foo*bar_foobar2281=== RUN TestGlobMatch/foo*bar_foo123bar2282=== PAUSE TestGlobMatch/foo*bar_foo123bar2283=== RUN TestGlobMatch/foo*bar_foobarbaz2284=== PAUSE TestGlobMatch/foo*bar_foobarbaz2285=== RUN TestGlobMatch/*/*_foo/bar2286=== PAUSE TestGlobMatch/*/*_foo/bar2287=== RUN TestGlobMatch/*/*_foo2288=== PAUSE TestGlobMatch/*/*_foo2289=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2290=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2291=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02292=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02293=== RUN TestGlobMatch/refs/*/main_refs/heads/main2294=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2295=== RUN TestGlobMatch/fo?_foo2296=== PAUSE TestGlobMatch/fo?_foo2297=== RUN TestGlobMatch/fo?_fo2298=== PAUSE TestGlobMatch/fo?_fo2299=== RUN TestGlobMatch/fo?_fooo2300=== PAUSE TestGlobMatch/fo?_fooo2301=== RUN TestGlobMatch/?oo_foo2302=== PAUSE TestGlobMatch/?oo_foo2303=== RUN TestGlobMatch/?oo_boo2304=== PAUSE TestGlobMatch/?oo_boo2305=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2306=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2307=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2308=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2309=== CONT TestGlobMatch/foo_foo2310=== CONT TestGlobMatch/*/*_foo/bar2311=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2312=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2313=== CONT TestGlobMatch/?oo_boo2314=== CONT TestGlobMatch/?oo_foo2315=== CONT TestGlobMatch/fo?_fooo2316=== CONT TestGlobMatch/fo?_fo2317=== CONT TestGlobMatch/fo?_foo2318=== CONT TestGlobMatch/refs/*/main_refs/heads/main2319=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02320=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2321=== CONT TestGlobMatch/*/*_foo2322=== CONT TestGlobMatch/*bar_bar2323=== CONT TestGlobMatch/foo*bar_foobarbaz2324=== CONT TestGlobMatch/foo*bar_foo123bar2325=== CONT TestGlobMatch/foo*bar_foobar2326=== CONT TestGlobMatch/*bar_foo2327=== CONT TestGlobMatch/*bar_foobar2328=== CONT TestGlobMatch/foo*_foo2329=== CONT TestGlobMatch/foo*_bar2330=== CONT TestGlobMatch/foo*_foobar2331=== CONT TestGlobMatch/*_2332=== CONT TestGlobMatch/*_anything2333=== CONT TestGlobMatch/foo_bar2334--- PASS: TestGlobMatch (0.01s)2335 --- PASS: TestGlobMatch/foo_foo (0.00s)2336 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2337 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2338 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2339 --- PASS: TestGlobMatch/?oo_boo (0.00s)2340 --- PASS: TestGlobMatch/?oo_foo (0.00s)2341 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2342 --- PASS: TestGlobMatch/fo?_fo (0.00s)2343 --- PASS: TestGlobMatch/fo?_foo (0.00s)2344 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2345 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2346 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2347 --- PASS: TestGlobMatch/*/*_foo (0.00s)2348 --- PASS: TestGlobMatch/*bar_bar (0.00s)2349 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2350 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2351 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2352 --- PASS: TestGlobMatch/*bar_foo (0.00s)2353 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2354 --- PASS: TestGlobMatch/foo*_foo (0.00s)2355 --- PASS: TestGlobMatch/foo*_bar (0.00s)2356 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2357 --- PASS: TestGlobMatch/*_ (0.00s)2358 --- PASS: TestGlobMatch/*_anything (0.00s)2359 --- PASS: TestGlobMatch/foo_bar (0.00s)23602026/10/25 19:01:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55274/oidc2361--- PASS: TestValidateToken_BoundClaimsMismatch (0.08s)23622026/10/25 19:01:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55278/oidc23632026/10/25 19:01:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55276/oidc2364--- PASS: TestPins_ReservedForMatchingRule (0.09s)23652026/10/25 19:01:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55284/oidc23662026/10/25 19:01:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55282/oidc2367--- PASS: TestValidateToken_WrongAudience (0.09s)2368--- PASS: TestPins_TopLevelShorthand (0.07s)2369--- PASS: TestScopes_Rules (0.08s)23702026/10/25 19:01:43 http: TLS handshake error from 127.0.0.1:55281: read tcp 127.0.0.1:55277->127.0.0.1:55281: use of closed network connection2371--- PASS: TestNewValidator_KubernetesRequiresCA (0.08s)23722026/10/25 19:01:43 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:55286/oidc2373--- PASS: TestValidateToken_NoMatchingProvider (0.12s)23742026/10/25 19:01:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55290/oidc2375--- PASS: TestValidateToken_Expired (0.14s)23762026/10/25 19:01:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55292/oidc23772026/10/25 19:01:43 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:55289/oidc23782026/10/25 19:01:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55293/oidc23792026/10/25 19:01:43 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:55295/oidc23802026/10/25 19:01:43 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232381--- PASS: TestValidateToken_MultipleProviders (0.18s)2382--- PASS: TestValidateToken_BoundSubjectMismatch (0.18s)23832026/10/25 19:01:43 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:552942384--- PASS: TestValidateToken_ValidToken (0.17s)2385--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.16s)2386--- PASS: TestValidateToken_KubernetesServiceAccount (0.17s)23872026/10/25 19:01:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55303/oidc2388--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.17s)2389PASS2390Running hook tests...2391=== RUN TestSendPathsEmpty2392=== PAUSE TestSendPathsEmpty2393=== RUN TestQueueEnqueueAndFetch2394=== PAUSE TestQueueEnqueueAndFetch2395=== RUN TestQueueDeduplication2396=== PAUSE TestQueueDeduplication2397=== RUN TestQueueRemove2398=== PAUSE TestQueueRemove2399=== RUN TestQueueFetchBatchLimit2400=== PAUSE TestQueueFetchBatchLimit2401=== RUN TestQueueRetryMovesToBack2402=== PAUSE TestQueueRetryMovesToBack2403=== RUN TestQueueFetchRemoveLifecycle2404=== PAUSE TestQueueFetchRemoveLifecycle2405=== RUN TestQueueConcurrentWriters2406=== PAUSE TestQueueConcurrentWriters2407=== RUN TestQueueRemoveLargeClosure2408=== PAUSE TestQueueRemoveLargeClosure2409=== RUN TestServerClientIntegration2410--- PASS: TestServerClientIntegration (0.00s)2411=== RUN TestServerQueueError24122026/10/25 19:01:43 ERROR Failed to queue paths error="permission denied" count=12413--- PASS: TestServerQueueError (0.00s)2414=== RUN TestGetListenerSocketActivation2415 server_test.go:145: systemd socket activation does not exist on darwin2416--- SKIP: TestGetListenerSocketActivation (0.00s)2417=== RUN TestServerStalledClientDoesNotBlockShutdown2418=== PAUSE TestServerStalledClientDoesNotBlockShutdown2419=== RUN TestServerBacksOffOnAcceptErrors2420=== PAUSE TestServerBacksOffOnAcceptErrors2421=== RUN TestDrainIsolatesPoisonPath2422=== PAUSE TestDrainIsolatesPoisonPath2423=== RUN TestRunNotBlockedByPoisonHead2424=== PAUSE TestRunNotBlockedByPoisonHead2425=== RUN TestDrainGivesUpWhenServerDown2426=== PAUSE TestDrainGivesUpWhenServerDown2427=== RUN TestFailedPathPrunedByLaterClosure2428=== PAUSE TestFailedPathPrunedByLaterClosure2429=== RUN TestWorkerUploadsAndRemoves2430=== PAUSE TestWorkerUploadsAndRemoves2431=== RUN TestWorkerSkipsGCdPaths2432=== PAUSE TestWorkerSkipsGCdPaths2433=== RUN TestWorkerPrunesClosureDeps2434=== PAUSE TestWorkerPrunesClosureDeps2435=== RUN TestDrainTimeout2436=== PAUSE TestDrainTimeout2437=== RUN TestWorkerRemoveFailureIsNotProgress2438=== PAUSE TestWorkerRemoveFailureIsNotProgress2439=== RUN TestWorkerKeepsPathItCannotStat2440=== PAUSE TestWorkerKeepsPathItCannotStat2441=== CONT TestSendPathsEmpty2442=== CONT TestWorkerUploadsAndRemoves2443--- PASS: TestSendPathsEmpty (0.00s)2444=== CONT TestWorkerKeepsPathItCannotStat2445=== CONT TestWorkerRemoveFailureIsNotProgress2446=== CONT TestDrainTimeout2447=== CONT TestWorkerPrunesClosureDeps2448=== CONT TestWorkerSkipsGCdPaths2449=== CONT TestDrainIsolatesPoisonPath2450=== CONT TestServerBacksOffOnAcceptErrors2451=== CONT TestServerStalledClientDoesNotBlockShutdown24522026/10/25 19:01:43 ERROR Accept failed error="too many open files"2453=== CONT TestQueueRemoveLargeClosure2454=== CONT TestDrainGivesUpWhenServerDown2455=== CONT TestQueueConcurrentWriters2456=== NAME TestServerStalledClientDoesNotBlockShutdown2457 server_test.go:232: listen: listen unix /private/var/tb/1/scratch/b566a4a9a208906d/build/TestServerStalledClientDoesNotBlockShutdown3433189455/001/test.sock: bind: invalid argument2458=== CONT TestFailedPathPrunedByLaterClosure2459=== CONT TestQueueFetchRemoveLifecycle2460=== CONT TestQueueRemove2461=== CONT TestQueueDeduplication2462=== CONT TestQueueRetryMovesToBack2463--- FAIL: TestServerStalledClientDoesNotBlockShutdown (0.00s)2464=== CONT TestQueueEnqueueAndFetch2465=== CONT TestQueueFetchBatchLimit2466=== CONT TestRunNotBlockedByPoisonHead24672026/10/25 19:01:43 ERROR Accept failed error="too many open files"24682026/10/25 19:01:43 INFO Uploading batch count=124692026/10/25 19:01:43 ERROR Upload failed error="upload failed" count=124702026/10/25 19:01:43 INFO Upload queue status pending=324712026/10/25 19:01:43 INFO Uploading batch count=224722026/10/25 19:01:43 ERROR Upload failed error="upload failed" count=224732026/10/25 19:01:43 INFO Upload queue status pending=224742026/10/25 19:01:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestWorkerSkipsGCdPaths2064827235/002/nonexistent24752026/10/25 19:01:43 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestDrainGivesUpWhenServerDown757963035/002/a24762026/10/25 19:01:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestWorkerRemoveFailureIsNotProgress1640306649/002/nonexistent24772026/10/25 19:01:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124782026/10/25 19:01:43 INFO Uploading batch count=124792026/10/25 19:01:43 ERROR Upload failed error="upload failed" count=124802026/10/25 19:01:43 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestWorkerKeepsPathItCannotStat2085767989/002/locked/aaa error="stat /private/var/tb/1/scratch/b566a4a9a208906d/build/TestWorkerKeepsPathItCannotStat2085767989/002/locked/aaa: permission denied"2481--- PASS: TestQueueDeduplication (0.02s)2482--- PASS: TestQueueRetryMovesToBack (0.02s)24832026/10/25 19:01:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestWorkerRemoveFailureIsNotProgress1640306649/002/nonexistent24842026/10/25 19:01:43 INFO Uploading batch count=124852026/10/25 19:01:43 ERROR Accept failed error="too many open files"24862026/10/25 19:01:43 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestDrainGivesUpWhenServerDown757963035/002/b24872026/10/25 19:01:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124882026/10/25 19:01:43 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestWorkerRemoveFailureIsNotProgress1640306649/002/nonexistent24892026/10/25 19:01:43 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124902026/10/25 19:01:43 INFO Uploading batch count=124912026/10/25 19:01:43 INFO Uploading batch count=124922026/10/25 19:01:43 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestWorkerKeepsPathItCannotStat2085767989/002/locked/aaa error="stat /private/var/tb/1/scratch/b566a4a9a208906d/build/TestWorkerKeepsPathItCannotStat2085767989/002/locked/aaa: permission denied"2493--- PASS: TestQueueFetchRemoveLifecycle (0.02s)24942026/10/25 19:01:43 ERROR Drain finished with paths left in queue remaining=12495--- PASS: TestQueueFetchBatchLimit (0.02s)24962026/10/25 19:01:43 INFO Upload queue status pending=224972026/10/25 19:01:43 INFO Uploading batch count=124982026/10/25 19:01:43 INFO Uploading batch count=224992026/10/25 19:01:43 ERROR Upload failed error="upload failed" count=225002026/10/25 19:01:43 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestDrainGivesUpWhenServerDown757963035/002/c25012026/10/25 19:01:43 INFO Uploading batch count=225022026/10/25 19:01:43 INFO Uploading batch count=425032026/10/25 19:01:43 ERROR Upload failed error="upload failed" count=425042026/10/25 19:01:43 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestDrainGivesUpWhenServerDown757963035/002/d25052026/10/25 19:01:43 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestDrainIsolatesPoisonPath3849209101/002/bbb25062026/10/25 19:01:43 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestWorkerKeepsPathItCannotStat2085767989/002/locked/aaa error="stat /private/var/tb/1/scratch/b566a4a9a208906d/build/TestWorkerKeepsPathItCannotStat2085767989/002/locked/aaa: permission denied"25072026/10/25 19:01:43 INFO Upload queue status pending=225082026/10/25 19:01:43 ERROR Drain finished with paths left in queue remaining=125092026/10/25 19:01:43 INFO Uploading batch count=22510--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)2511--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)25122026/10/25 19:01:43 INFO Uploading batch count=225132026/10/25 19:01:43 ERROR Upload failed error="upload failed" count=225142026/10/25 19:01:43 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestDrainGivesUpWhenServerDown757963035/002/e25152026/10/25 19:01:43 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/b566a4a9a208906d/build/TestDrainGivesUpWhenServerDown757963035/002/f2516--- PASS: TestQueueEnqueueAndFetch (0.02s)25172026/10/25 19:01:43 INFO Uploading batch count=125182026/10/25 19:01:43 ERROR Upload failed error="upload failed" count=12519--- PASS: TestQueueRemove (0.02s)25202026/10/25 19:01:43 INFO Uploading batch count=125212026/10/25 19:01:43 ERROR Upload failed error="upload failed" count=125222026/10/25 19:01:43 ERROR Drain finished with paths left in queue remaining=1025232026/10/25 19:01:43 INFO Uploading batch count=125242026/10/25 19:01:43 ERROR Upload failed error="upload failed" count=125252026/10/25 19:01:43 ERROR Drain finished with paths left in queue remaining=12526--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2527--- PASS: TestDrainIsolatesPoisonPath (0.02s)2528--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2529--- PASS: TestWorkerSkipsGCdPaths (0.03s)25302026/10/25 19:01:43 ERROR Accept failed error="too many open files"2531--- PASS: TestWorkerPrunesClosureDeps (0.04s)2532--- PASS: TestWorkerUploadsAndRemoves (0.04s)2533--- PASS: TestQueueRemoveLargeClosure (0.05s)25342026/10/25 19:01:43 ERROR Accept failed error="too many open files"25352026/10/25 19:01:44 ERROR Accept failed error="too many open files"2536--- PASS: TestQueueConcurrentWriters (0.16s)25372026/10/25 19:01:44 ERROR Upload failed error="context deadline exceeded" count=225382026/10/25 19:01:44 ERROR Drain finished with paths left in queue remaining=42539--- PASS: TestDrainTimeout (0.22s)25402026/10/25 19:01:44 ERROR Accept failed error="too many open files"25412026/10/25 19:01:44 ERROR Accept failed error="too many open files"2542--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)25432026/10/25 19:01:44 INFO Uploading batch count=125442026/10/25 19:01:44 INFO Uploading batch count=125452026/10/25 19:01:44 INFO Uploading batch count=125462026/10/25 19:01:44 ERROR Upload failed error="upload failed" count=125472026/10/25 19:01:44 INFO Uploading batch count=125482026/10/25 19:01:44 ERROR Upload failed error="upload failed" count=125492026/10/25 19:01:44 INFO Uploading batch count=125502026/10/25 19:01:44 ERROR Upload failed error="upload failed" count=125512026/10/25 19:01:44 INFO Uploading batch count=125522026/10/25 19:01:44 ERROR Upload failed error="upload failed" count=125532026/10/25 19:01:44 ERROR Drain finished with paths left in queue remaining=12554--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2555FAIL