niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #479
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestPushPathsRefusesUntrustedClosure4--- PASS: TestPushPathsRefusesUntrustedClosure (0.21s)5=== RUN TestDoServerRequestAttachesToken6=== PAUSE TestDoServerRequestAttachesToken7=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry8=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry9=== RUN TestRegisterUploadedObjectReusesConnections10=== PAUSE TestRegisterUploadedObjectReusesConnections11=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica12=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica13=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun14=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun15=== RUN TestCaseHackSuffix16=== PAUSE TestCaseHackSuffix17=== RUN TestFilterOversizedClosures18=== PAUSE TestFilterOversizedClosures19=== RUN TestUploadMultipart_PartsInParallel20=== PAUSE TestUploadMultipart_PartsInParallel21=== RUN TestUploadMultipart_ReturnsAfterDroppedBody22=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody23=== RUN TestPartSizeForNAR24=== PAUSE TestPartSizeForNAR25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.07s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestDumpPathMatchesNix30=== PAUSE TestDumpPathMatchesNix31=== RUN TestDumpPathSingleFile32=== PAUSE TestDumpPathSingleFile33=== RUN TestDumpPathWriterError34=== PAUSE TestDumpPathWriterError35=== RUN TestEncodeNixBase3236=== PAUSE TestEncodeNixBase3237=== RUN TestEncodeNixBase32WithRealHash38=== PAUSE TestEncodeNixBase32WithRealHash39=== RUN TestConvertHashToNix3240=== PAUSE TestConvertHashToNix3241=== RUN TestGetStorePathHash42=== PAUSE TestGetStorePathHash43=== RUN TestPathInfoHashCompatibility44=== PAUSE TestPathInfoHashCompatibility45=== RUN TestParsePathInfoJSON46=== PAUSE TestParsePathInfoJSON47=== RUN TestParsePathInfoJSONMultiplePaths48=== PAUSE TestParsePathInfoJSONMultiplePaths49=== RUN TestPathInfoCACompatibility50=== PAUSE TestPathInfoCACompatibility51=== RUN TestRateLimiterFeedback52=== PAUSE TestRateLimiterFeedback53=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess54=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess55=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer56=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer57=== RUN TestRegisterUploadedObject_OutlivesPush58=== PAUSE TestRegisterUploadedObject_OutlivesPush59=== 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=== RUN TestUntrustedPaths116=== PAUSE TestUntrustedPaths117=== RUN TestUntrustedPathsContentAddressed118=== PAUSE TestUntrustedPathsContentAddressed119=== RUN TestParsePathInfoUltimate120=== PAUSE TestParsePathInfoUltimate121=== CONT TestDoServerRequestAttachesToken122=== CONT TestDoWithRetry_FinalResponseBodyReadable123=== CONT TestEncodeNixBase32WithRealHash124--- PASS: TestEncodeNixBase32WithRealHash (0.00s)125=== CONT TestScriptTokenScriptFails126=== CONT TestRetryTimeoutOutlastsMaxRetries127=== CONT TestDoWithRetry_BodyReplayedViaGetBody128=== CONT TestResolveStorePath129=== CONT TestRegisterUploadedObject_OutlivesPush1302026/11/10 21:11:39 WARN Rate limiter enabled after throttle name=server-test rate=5131=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer132=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess133=== CONT TestRateLimiterFeedback1342026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:52752135=== RUN TestRateLimiterFeedback/429_enables_limiter136=== PAUSE TestRateLimiterFeedback/429_enables_limiter137=== RUN TestRateLimiterFeedback/503_enables_limiter138=== PAUSE TestRateLimiterFeedback/503_enables_limiter139=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter140=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter141=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter142=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter143=== CONT TestPathInfoCACompatibility144=== RUN TestPathInfoCACompatibility/null_ca_field145=== CONT TestParsePathInfoJSONMultiplePaths146=== CONT TestParsePathInfoJSON147=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths148=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths149=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths1502026/11/10 21:11:39 WARN Rate limiter backed off name=server-test rate=5151=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths1522026/11/10 21:11:39 WARN Rate limiter enabled after throttle name=server-test rate=5153=== RUN TestParsePathInfoJSON/Nix_format154=== CONT TestGetStorePathHash155=== RUN TestGetStorePathHash/valid_store_path156=== CONT TestConvertHashToNix32157=== RUN TestConvertHashToNix32/SRI_format_to_Nix32158=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32159=== CONT TestDumpPathSingleFile160=== CONT TestEncodeNixBase32161=== CONT TestDumpPathWriterError162=== CONT TestSetClientTLSErrors163=== CONT TestParsePathInfoUltimate164=== CONT TestUntrustedPathsContentAddressed165=== CONT TestUntrustedPaths166=== CONT TestScriptTokenEmptyCommand167=== CONT TestUploadMultipart_PartsInParallel168=== PAUSE TestPathInfoCACompatibility/null_ca_field169--- PASS: TestDoServerRequestAttachesToken (0.00s)170=== CONT TestScriptTokenBadJSON171--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)172=== RUN TestUntrustedPaths/server_without_policy_accepts_anything173=== PAUSE TestUntrustedPaths/server_without_policy_accepts_anything174=== RUN TestUntrustedPaths/built_locally175=== PAUSE TestUntrustedPaths/built_locally176=== RUN TestUntrustedPaths/signed_by_the_server_key177=== PAUSE TestUntrustedPaths/signed_by_the_server_key178=== RUN TestUntrustedPaths/signed_by_an_upstream_key179=== PAUSE TestUntrustedPaths/signed_by_an_upstream_key180=== RUN TestUntrustedPaths/unsigned_substitute181=== PAUSE TestParsePathInfoJSON/Nix_format182=== RUN TestParsePathInfoJSON/Lix_format183=== PAUSE TestParsePathInfoJSON/Lix_format184=== CONT TestScriptTokenEmptyToken185=== CONT TestDumpPathMatchesNix186=== PAUSE TestGetStorePathHash/valid_store_path1872026/11/10 21:11:39 WARN Rate limiter enabled after throttle name=server-test rate=51882026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:527561892026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:52758190=== RUN TestConvertHashToNix32/already_Nix32_format191=== RUN TestEncodeNixBase32/test_string_hash192=== CONT TestPathInfoHashCompatibility193=== PAUSE TestEncodeNixBase32/test_string_hash194=== CONT TestScriptTokenCachesUntilRefresh195=== RUN TestEncodeNixBase32/empty_input196=== PAUSE TestEncodeNixBase32/empty_input197=== CONT TestUploadMultipart_ReturnsAfterDroppedBody1982026/11/10 21:11:39 WARN Rate limiter backed off name=server-test rate=5199=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)2002026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:52758201=== CONT TestFileTokenReadsAndCaches202=== RUN TestParsePathInfoJSON/empty_input203=== PAUSE TestParsePathInfoJSON/empty_input204=== RUN TestParsePathInfoJSON/whitespace_only205=== PAUSE TestParsePathInfoJSON/whitespace_only206--- PASS: TestResolveStorePath (0.00s)207--- PASS: TestScriptTokenEmptyCommand (0.00s)208--- PASS: TestUntrustedPathsContentAddressed (0.00s)209--- PASS: TestParsePathInfoUltimate (0.00s)210--- PASS: TestRegisterUploadedObject_OutlivesPush (0.01s)211--- PASS: TestScriptTokenScriptFails (0.01s)212=== RUN TestSetClientTLSErrors/missing_cert_file213=== PAUSE TestSetClientTLSErrors/missing_cert_file214=== RUN TestSetClientTLSErrors/missing_key_file215=== PAUSE TestSetClientTLSErrors/missing_key_file216=== RUN TestSetClientTLSErrors/missing_ca_file217=== PAUSE TestSetClientTLSErrors/missing_ca_file218=== RUN TestSetClientTLSErrors/invalid_ca_file219=== CONT TestScriptTokenNoExpiryRerunsEveryCall220=== RUN TestPathInfoCACompatibility/old_string_format_-_text221=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text222=== CONT TestPartSizeForNAR223=== CONT TestFileTokenEmpty224=== RUN TestPartSizeForNAR/zero_stays_at_minimum225=== CONT TestFileTokenMissing226=== RUN TestGetStorePathHash/basename_without_hyphen_should_error227--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)228=== CONT TestStaticToken229--- PASS: TestStaticToken (0.00s)230=== CONT TestStreamPushRequestLine231=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error232=== PAUSE TestConvertHashToNix32/already_Nix32_format233=== PAUSE TestUntrustedPaths/unsigned_substitute234=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)235=== RUN TestParsePathInfoJSON/invalid_JSON236=== PAUSE TestSetClientTLSErrors/invalid_ca_file237=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2382026/11/10 21:11:39 ERROR Upload failed error=boom count=1239=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive240=== RUN TestPathInfoCACompatibility/new_structured_format_-_text241=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text242=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon243=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon244=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error245=== RUN TestConvertHashToNix32/invalid_format246=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error247=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error248=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error249=== PAUSE TestConvertHashToNix32/invalid_format250=== PAUSE TestParsePathInfoJSON/invalid_JSON251=== CONT TestStreamPushReportsSkippedPaths2522026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:52756253=== CONT TestSetClientTLS254--- PASS: TestStreamPushReportsSkippedPaths (0.00s)255=== CONT TestStreamPushReportsSignatures2562026/11/10 21:11:39 ERROR Upload failed error=boom count=1257--- PASS: TestStreamPushReportsSignatures (0.00s)258=== CONT TestStreamPushStopsWhenCanceled259--- PASS: TestStreamPushStopsWhenCanceled (0.00s)260=== CONT TestStreamPushBatchesUnderLoad261=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false262=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false263=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true264=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true265=== CONT TestShellSplitErrors266--- PASS: TestShellSplitErrors (0.00s)267--- PASS: TestFileTokenReadsAndCaches (0.00s)268=== CONT TestStreamPushGivesUpOnDeadServer269=== CONT TestStreamPushReportsEveryPath270--- PASS: TestFileTokenEmpty (0.00s)271=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method272=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method273=== CONT TestStreamPushIsolatesFailures274=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum275=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI276=== CONT TestRegisterUploadedObjectReusesConnections277=== RUN TestPartSizeForNAR/small_stays_at_minimum278=== PAUSE TestPartSizeForNAR/small_stays_at_minimum279=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum280=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum281=== RUN TestUntrustedPaths/signed_only_by_another_key2822026/11/10 21:11:39 ERROR Upload failed error="connection refused" count=20283=== PAUSE TestUntrustedPaths/signed_only_by_another_key2842026/11/10 21:11:39 ERROR Server seems unavailable, giving up on batch untried=17285=== RUN TestUntrustedPaths/another_key's_signature_under_the_server_key_name2862026/11/10 21:11:39 ERROR Upload failed error="bad path" count=3287=== PAUSE TestUntrustedPaths/another_key's_signature_under_the_server_key_name288=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI289=== CONT TestClientSignaturesByStorePath290=== CONT TestFilterOversizedClosures291=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica292=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512293=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512294=== CONT TestSetClientTLSDoesNotMutateDefaultTransport295=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry296=== CONT TestCaseHackSuffix297=== CONT TestShellSplit298=== CONT TestRateLimiterFeedback/429_enables_limiter299=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun300=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts301=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts302=== RUN TestPartSizeForNAR/1_TiB303=== PAUSE TestPartSizeForNAR/1_TiB304=== RUN TestUntrustedPaths/server_signature_over_different_contents305=== PAUSE TestUntrustedPaths/server_signature_over_different_contents306=== RUN TestFilterOversizedClosures/no_limit_keeps_everything307--- PASS: TestStreamPushReportsEveryPath (0.00s)308--- PASS: TestFileTokenMissing (0.00s)309--- PASS: TestStreamPushIsolatesFailures (0.00s)310--- PASS: TestClientSignaturesByStorePath (0.00s)311--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)312--- PASS: TestShellSplit (0.00s)313=== RUN TestPartSizeForNAR/5_TiB_S3_max_object314=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object315=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter316=== RUN TestPartSizeForNAR/capped_at_5_GiB317=== PAUSE TestPartSizeForNAR/capped_at_5_GiB318=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything319=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped320=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped321=== RUN TestFilterOversizedClosures/all_closures_skipped322=== PAUSE TestFilterOversizedClosures/all_closures_skipped323=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter324=== CONT TestRateLimiterFeedback/503_enables_limiter325--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.00s)326=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths327=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths328--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)329 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)330 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)331=== CONT TestEncodeNixBase32/test_string_hash332=== CONT TestEncodeNixBase32/empty_input333--- PASS: TestEncodeNixBase32 (0.00s)334 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)335 --- PASS: TestEncodeNixBase32/empty_input (0.00s)336=== CONT TestSetClientTLSErrors/missing_cert_file337=== CONT TestSetClientTLSErrors/invalid_ca_file3382026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:52756339=== CONT TestSetClientTLSErrors/missing_ca_file340--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)341=== CONT TestGetStorePathHash/valid_store_path342=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error343=== CONT TestSetClientTLSErrors/missing_key_file344=== CONT TestGetStorePathHash/basename_without_hyphen_should_error345=== RUN TestSetClientTLS/rejects_connection_without_client_cert346=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert347=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error348=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA349=== CONT TestConvertHashToNix32/SRI_format_to_Nix32350=== CONT TestParsePathInfoJSON/invalid_JSON351--- PASS: TestSetClientTLSErrors (0.01s)352 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)353 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)354 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)355 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)356=== CONT TestParsePathInfoJSON/Nix_format357=== CONT TestParsePathInfoJSON/empty_input358=== CONT TestParsePathInfoJSON/Lix_format359=== CONT TestConvertHashToNix32/already_Nix32_format360=== CONT TestConvertHashToNix32/invalid_format361=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false362=== CONT TestParsePathInfoJSON/whitespace_only363=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true364--- PASS: TestGetStorePathHash (0.01s)365 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)366 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)367 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)368 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)369=== CONT TestPathInfoCACompatibility/null_ca_field370--- PASS: TestConvertHashToNix32 (0.01s)371 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)372 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)373 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)374=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA375=== RUN TestSetClientTLS/preserves_debug_logging_transport376--- PASS: TestParsePathInfoJSON (0.01s)377 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)378 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)379 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)380 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)381 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)382=== PAUSE TestSetClientTLS/preserves_debug_logging_transport383--- PASS: TestStreamPushBatchesUnderLoad (0.00s)384 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)385 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)386=== CONT TestPathInfoCACompatibility/new_structured_format_-_text387=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method388=== CONT TestPathInfoCACompatibility/old_string_format_-_text389=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)390=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive391--- PASS: TestPathInfoCACompatibility (0.01s)392 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)393 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)394 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)395 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)396 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)397=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512398=== CONT TestUntrustedPaths/server_without_policy_accepts_anything399=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon400=== CONT TestUntrustedPaths/signed_only_by_another_key401=== CONT TestUntrustedPaths/another_key's_signature_under_the_server_key_name4022026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:527564032026/11/10 21:11:39 INFO Garbage collection started4042026/11/10 21:11:39 WARN Rate limiter enabled after throttle name=s3-test rate=54052026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:52780406=== CONT TestUntrustedPaths/signed_by_an_upstream_key407=== CONT TestUntrustedPaths/unsigned_substitute408=== CONT TestUntrustedPaths/signed_by_the_server_key409=== CONT TestUntrustedPaths/built_locally410=== CONT TestPartSizeForNAR/zero_stays_at_minimum411=== CONT TestFilterOversizedClosures/no_limit_keeps_everything412=== CONT TestPartSizeForNAR/capped_at_5_GiB413=== CONT TestPartSizeForNAR/1_TiB414=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts415=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum416=== CONT TestPartSizeForNAR/small_stays_at_minimum417=== CONT TestPartSizeForNAR/5_TiB_S3_max_object418--- PASS: TestPartSizeForNAR (0.00s)419 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)420 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)421 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)422 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)423 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)424 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)425 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)426=== CONT TestFilterOversizedClosures/all_closures_skipped427=== CONT TestUntrustedPaths/server_signature_over_different_contents428=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI429=== CONT TestSetClientTLS/rejects_connection_without_client_cert430--- PASS: TestPathInfoHashCompatibility (0.00s)431 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)432 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)433 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)434 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)435=== CONT TestSetClientTLS/preserves_debug_logging_transport436=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped437--- PASS: TestUntrustedPaths (0.01s)438 --- PASS: TestUntrustedPaths/server_without_policy_accepts_anything (0.00s)439 --- PASS: TestUntrustedPaths/signed_only_by_another_key (0.00s)440 --- PASS: TestUntrustedPaths/another_key's_signature_under_the_server_key_name (0.00s)441 --- PASS: TestUntrustedPaths/unsigned_substitute (0.00s)442 --- PASS: TestUntrustedPaths/signed_by_an_upstream_key (0.00s)443 --- PASS: TestUntrustedPaths/built_locally (0.00s)444 --- PASS: TestUntrustedPaths/signed_by_the_server_key (0.00s)445 --- PASS: TestUntrustedPaths/server_signature_over_different_contents (0.00s)446=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA447--- PASS: TestStreamPushRequestLine (0.01s)448--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)4492026/11/10 21:11:39 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=504502026/11/10 21:11:39 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000451--- PASS: TestFilterOversizedClosures (0.00s)452 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)453 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)454 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)4552026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:527564562026/11/10 21:11:39 INFO Garbage collection started4572026/11/10 21:11:39 WARN Rate limiter enabled after throttle name=server-test rate=54582026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:527774592026/11/10 21:11:39 WARN Rate limiter enabled after throttle name=server-test rate=54602026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:527734612026/11/10 21:11:39 WARN Rate limiter backed off name=server-test rate=54622026/11/10 21:11:39 WARN Rate limiter backed off name=server-test rate=54632026/11/10 21:11:39 INFO Garbage collection progress phase=running_on_another_replica failed_uploads_deleted=0 old_closures_deleted=0 objects_marked=0 objects_deleted=0 objects_failed=0464--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)465--- PASS: TestRateLimiterFeedback (0.00s)466 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)467 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)468 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)469 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)470--- PASS: TestScriptTokenBadJSON (0.02s)471--- PASS: TestScriptTokenEmptyToken (0.02s)4722026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:527564732026/11/10 21:11:39 WARN Garbage collection finished on another replica. Its statistics are not available here474--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)4752026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:527564762026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:527564772026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:527564782026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:527564792026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:527564802026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:527564812026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:527564822026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:527564832026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:52756484--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)4852026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:527564862026/11/10 21:11:39 http: TLS handshake error from 127.0.0.1:52818: remote error: tls: bad certificate4872026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:52756488--- PASS: TestSetClientTLS (0.01s)489 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)490 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)491 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)4922026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:527564932026/11/10 21:11:39 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:52756494--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)495--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)496--- PASS: TestDumpPathWriterError (0.06s)497--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)498--- PASS: TestCaseHackSuffix (0.06s)499--- PASS: TestDumpPathSingleFile (0.07s)500--- PASS: TestDumpPathMatchesNix (0.09s)5012026/11/10 21:11:39 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52759/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52759/api/uploads/complete5022026/11/10 21:11:39 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"5032026/11/10 21:11:39 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52759/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52759/api/uploads/complete5042026/11/10 21:11:39 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"5052026/11/10 21:11:39 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52759/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52759/api/uploads/complete5062026/11/10 21:11:39 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"507--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.10s)508--- PASS: TestUploadMultipart_PartsInParallel (0.62s)509--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)510PASS511Running server tests...512The files belonging to this database system will be owned by user "_tribuchetbld6".513This user must also own the server process.514515The database cluster will be initialized with locale "C".516The default database encoding has accordingly been set to "SQL_ASCII".517The default text search configuration will be set to "english".518519Data page checksums are enabled.520521creating directory /private/var/tb/6/scratch/509dce1726107d78/build/postgres1446617331/data ... ok522creating subdirectories ... ok523selecting dynamic shared memory implementation ... posix524selecting default "max_connections" ... 100525selecting default "shared_buffers" ... 128MB526selecting default time zone ... UTC527creating configuration files ... ok528running bootstrap script ... ok529performing post-bootstrap initialization ... ok530syncing data to disk ... ok531532initdb: warning: enabling "trust" authentication for local connections533initdb: 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.534535Success. You can now start the database server using:536537 pg_ctl -D /private/var/tb/6/scratch/509dce1726107d78/build/postgres1446617331/data -l logfile start5385392026-11-10 21:11:41.363 UTC [90935] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5402026-11-10 21:11:41.363 UTC [90935] LOG: listening on Unix socket "/private/var/tb/6/scratch/509dce1726107d78/build/postgres1446617331/.s.PGSQL.5432"5412026-11-10 21:11:41.365 UTC [90942] LOG: database system was shut down at 2026-11-10 21:11:41 UTC5422026-11-10 21:11:41.365 UTC [90943] FATAL: the database system is starting up543/private/var/tb/6/scratch/509dce1726107d78/build/postgres1446617331:5432 - rejecting connections5442026-11-10 21:11:41.366 UTC [90935] LOG: database system is ready to accept connections545/private/var/tb/6/scratch/509dce1726107d78/build/postgres1446617331:5432 - accepting connections546{"timestamp":"2026-11-10T21:11:41.618757Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"c7c4e998-2871-45fc-ac99-60fa7ee48cb2","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":10,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}547{"timestamp":"2026-11-10T21:11:41.72624Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"5b21bb0a-3ec6-43d9-8bf9-be1f1ef737c2","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(5)"}548{"timestamp":"2026-11-10T21:11:41.830459Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"66a5c867-c7fe-4250-b85a-ad653bbb9fe6","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":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}549=== RUN TestAbortSucceeded550=== PAUSE TestAbortSucceeded551=== RUN TestService_AuthMiddleware552=== PAUSE TestService_AuthMiddleware553=== RUN TestService_AuthMiddleware_MTLSProxyHeader554=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader555=== RUN TestService_AuthMiddleware_MTLSBoundSubjects556=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects557=== RUN TestService_ReadAuthMiddleware558=== PAUSE TestService_ReadAuthMiddleware559=== RUN TestService_AuthMiddleware_OIDC560=== PAUSE TestService_AuthMiddleware_OIDC561=== RUN TestService_RequireScope_OIDC562=== PAUSE TestService_RequireScope_OIDC563=== RUN TestService_ReadScope_PublicByDefault564=== PAUSE TestService_ReadScope_PublicByDefault565=== RUN TestCacheConfigHandler566=== PAUSE TestCacheConfigHandler567=== RUN TestCacheStatsHandler568=== PAUSE TestCacheStatsHandler569=== RUN TestClientCADerivations570=== PAUSE TestClientCADerivations571=== RUN TestClientErrorHandling572=== PAUSE TestClientErrorHandling573=== RUN TestClientIntegration574=== PAUSE TestClientIntegration575=== RUN TestClientMultipleUploads576=== PAUSE TestClientMultipleUploads577=== RUN TestClientWithDependencies578=== PAUSE TestClientWithDependencies579=== RUN TestClientSharedPathCommittedMidPush580=== PAUSE TestClientSharedPathCommittedMidPush581=== RUN TestPinProtectsFromGC582=== PAUSE TestPinProtectsFromGC583=== RUN TestClientPushesUseOnePush584=== PAUSE TestClientPushesUseOnePush585=== RUN TestClientFallsBackToClosures586=== PAUSE TestClientFallsBackToClosures587=== RUN TestDeleteClosuresRacingPins588=== PAUSE TestDeleteClosuresRacingPins589=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock590=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock591=== RUN TestResolveDBConnectionString592=== PAUSE TestResolveDBConnectionString593=== RUN TestConnectWaitsForAPeerMigration594=== PAUSE TestConnectWaitsForAPeerMigration595=== RUN TestLeadElectsOneAndHandsOver596=== PAUSE TestLeadElectsOneAndHandsOver597=== RUN TestLeadIncumbentWinsAfterRestart5982026/11/10 21:11:42 INFO lead: acquired remote=192.0.2.1:12345992026/11/10 21:11:42 INFO lead: released remote=192.0.2.1:12346002026/11/10 21:11:42 INFO lead: acquired remote=192.0.2.1:12346012026/11/10 21:11:43 INFO lead: released remote=192.0.2.1:1234602--- PASS: TestLeadIncumbentWinsAfterRestart (1.93s)603=== RUN TestLeadIncumbentAnnouncesAtOnce604=== PAUSE TestLeadIncumbentAnnouncesAtOnce605=== RUN TestLeadEndsOnShutdown606=== PAUSE TestLeadEndsOnShutdown607=== RUN TestLeadEndsWhenItsConnectionHangs6082026/11/10 21:11:44 INFO lead: acquired remote=192.0.2.1:12346092026-11-10 21:11:45.225 UTC [90980] FATAL: terminating connection due to administrator command6102026/11/10 21:11:45 INFO lead: acquired remote=192.0.2.1:12346112026/11/10 21:11:46 WARN lead: lock connection lost error="timeout: context deadline exceeded"6122026/11/10 21:11:46 INFO lead: released remote=192.0.2.1:12346132026/11/10 21:11:46 INFO lead: released remote=192.0.2.1:1234614--- PASS: TestLeadEndsWhenItsConnectionHangs (2.76s)615=== RUN TestGCAdvisoryLockBlocksConcurrentRun616=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun617=== RUN TestGCBugBareHashReferences618=== PAUSE TestGCBugBareHashReferences619=== RUN TestGCMetrics620=== PAUSE TestGCMetrics621=== RUN TestPushDedupSurvivesConcurrentGC622=== PAUSE TestPushDedupSurvivesConcurrentGC623=== RUN TestDeduplicatedObjectsRecordedAsPending624=== PAUSE TestDeduplicatedObjectsRecordedAsPending625=== RUN TestGCSweepSkipsPendingObjects626=== PAUSE TestGCSweepSkipsPendingObjects627=== RUN TestTombstonedObjectOfferedWithoutWaiting628=== PAUSE TestTombstonedObjectOfferedWithoutWaiting629=== RUN TestGCSweepDeliversEachKeyOnce630=== PAUSE TestGCSweepDeliversEachKeyOnce631=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection632=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection633=== RUN TestForceGCDuringPushOffersSweptObject634=== PAUSE TestForceGCDuringPushOffersSweptObject635=== RUN TestFailedS3DeleteKeepsTombstone636=== PAUSE TestFailedS3DeleteKeepsTombstone637=== RUN TestSweepSkipsRowsLockedByPush638=== PAUSE TestSweepSkipsRowsLockedByPush639=== RUN TestRegisterCompletedObjectNeedsPendingRow640=== PAUSE TestRegisterCompletedObjectNeedsPendingRow641=== RUN TestGetExistingObjectsLocksRows642=== PAUSE TestGetExistingObjectsLocksRows643=== RUN TestSweepRechecksPendingAfterLocking644=== PAUSE TestSweepRechecksPendingAfterLocking645=== RUN TestPushWaitsForSweepHoldingRow646=== PAUSE TestPushWaitsForSweepHoldingRow647=== RUN TestCommitRacingPendingCleanupKeepsObjects648=== PAUSE TestCommitRacingPendingCleanupKeepsObjects649=== RUN TestGCEndsOnShutdown650=== PAUSE TestGCEndsOnShutdown651=== RUN TestGCTaskStore_StartNew652=== PAUSE TestGCTaskStore_StartNew653=== RUN TestGCTaskStore_DeduplicateSameParams654=== PAUSE TestGCTaskStore_DeduplicateSameParams655=== RUN TestGCTaskStore_ConflictDifferentParams656=== PAUSE TestGCTaskStore_ConflictDifferentParams657=== RUN TestGCTaskStore_GetEmpty658=== PAUSE TestGCTaskStore_GetEmpty659=== RUN TestGCTaskStore_GetReturnsLatest660=== PAUSE TestGCTaskStore_GetReturnsLatest661=== RUN TestGCTaskStore_CompletedAllowsNewTask662=== PAUSE TestGCTaskStore_CompletedAllowsNewTask663=== RUN TestGCTaskStore_PhaseUpdates664=== PAUSE TestGCTaskStore_PhaseUpdates665=== RUN TestGCTaskStore_Fail666=== PAUSE TestGCTaskStore_Fail667=== RUN TestGracefulShutdownDrainsInflight668=== PAUSE TestGracefulShutdownDrainsInflight669=== RUN TestService_healthCheckHandler670=== PAUSE TestService_healthCheckHandler671=== RUN TestService_readinessHandler672=== PAUSE TestService_readinessHandler673=== RUN TestGenerateLandingPage674=== PAUSE TestGenerateLandingPage675=== RUN TestEnsureAbortUploadsRule676=== PAUSE TestEnsureAbortUploadsRule677=== RUN TestCacheConfigHandlerMaxNarSize678=== PAUSE TestCacheConfigHandlerMaxNarSize679=== RUN TestCreatePendingClosureRejectsOversizedNAR680=== PAUSE TestCreatePendingClosureRejectsOversizedNAR681=== RUN TestNARDeduplicationMetadataUploadBug682=== PAUSE TestNARDeduplicationMetadataUploadBug683=== RUN TestMetricsInventory684=== PAUSE TestMetricsInventory685=== RUN TestMetricsCommit686=== PAUSE TestMetricsCommit687=== RUN TestService_NativeMTLS688=== PAUSE TestService_NativeMTLS689=== RUN TestServerTLSConfig690=== PAUSE TestServerTLSConfig691=== RUN TestMultipartCleanup692=== PAUSE TestMultipartCleanup693=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded694=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded695=== RUN TestPendingCleanupUsesOneCutoff696=== PAUSE TestPendingCleanupUsesOneCutoff697=== RUN TestObjectStatsTrigger698=== PAUSE TestObjectStatsTrigger699=== RUN TestObjectStatsUpdatedOncePerCommit700=== PAUSE TestObjectStatsUpdatedOncePerCommit701=== RUN TestOrphanedObjectsGC702=== PAUSE TestOrphanedObjectsGC703=== RUN TestOrphanedObjectsGCStressTest704=== PAUSE TestOrphanedObjectsGCStressTest705=== RUN TestCreatePin_ReservedPins706=== PAUSE TestCreatePin_ReservedPins707=== RUN TestPresentReportsOnlyClosureRoots708=== PAUSE TestPresentReportsOnlyClosureRoots709=== RUN TestPresentRefreshesOnlyStaleClosures710=== PAUSE TestPresentRefreshesOnlyStaleClosures711=== RUN TestPresentNotReportedWhileGCDeletesClosure712=== PAUSE TestPresentNotReportedWhileGCDeletesClosure713=== RUN TestParseSingleRange714=== PAUSE TestParseSingleRange715=== RUN TestProxyHeadersOnlyTrustedOnSocket7162026/11/10 21:11:46 INFO Starting HTTP server address=127.0.0.1:528837172026/11/10 21:11:46 INFO Starting HTTP server address=proxy.sock7182026/11/10 21:11:46 WARN mTLS auth: subject not in bound subjects subject="CN=someone"7192026/11/10 21:11:46 INFO Shutdown signal received, draining in-flight requests timeout=10s720--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)721=== RUN TestIsValidCachePath722=== PAUSE TestIsValidCachePath723=== RUN TestReadProxyNarinfo724=== PAUSE TestReadProxyNarinfo725=== RUN TestReadProxyNarinfoAlreadyDecompressed726=== PAUSE TestReadProxyNarinfoAlreadyDecompressed727=== RUN TestReadProxyContentNegotiation728=== PAUSE TestReadProxyContentNegotiation729=== RUN TestReadProxyNarStreaming730=== PAUSE TestReadProxyNarStreaming731=== RUN TestReadProxy404732=== PAUSE TestReadProxy404733=== RUN TestReadProxyInvalidPath734=== PAUSE TestReadProxyInvalidPath735=== RUN TestReadProxyHead736=== PAUSE TestReadProxyHead737=== RUN TestReadProxyOutlastsServerWriteTimeout738=== PAUSE TestReadProxyOutlastsServerWriteTimeout739=== RUN TestReadProxyConditionalGet740=== PAUSE TestReadProxyConditionalGet741=== RUN TestReadProxyRootRedirectsToIndexHTML742=== PAUSE TestReadProxyRootRedirectsToIndexHTML743=== RUN TestReadProxyDisabled744=== PAUSE TestReadProxyDisabled745=== RUN TestReadRedirectNar746=== PAUSE TestReadRedirectNar747=== RUN TestReadRedirectKeepsNarinfoProxied748=== PAUSE TestReadRedirectKeepsNarinfoProxied749=== RUN TestReadProxyRangeRequest750=== PAUSE TestReadProxyRangeRequest751=== RUN TestReadRedirectUsesPublicS3URL752=== PAUSE TestReadRedirectUsesPublicS3URL753=== RUN TestPush_OverlappingRootsStoreOneRowPerKey754=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey755=== RUN TestPush_CompleteCommitsEveryRoot756=== PAUSE TestPush_CompleteCommitsEveryRoot757=== RUN TestPush_RepeatedRootCommitsOnce758=== PAUSE TestPush_RepeatedRootCommitsOnce759=== RUN TestPush_CompleteWaitsForCleanupOfThePush760=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush761=== RUN TestPush_RootsAreLockedInByteOrder762=== PAUSE TestPush_RootsAreLockedInByteOrder763=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit764=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit765=== RUN TestPush_RejectsBadRequests766=== PAUSE TestPush_RejectsBadRequests767=== RUN TestPush_SignsNarinfosOfItsPendingObjects768=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects769=== RUN TestSharedNarBothUploadsComplete770=== PAUSE TestSharedNarBothUploadsComplete771=== RUN TestCompleteMultipartUpload_ErrorButObjectExists772=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists773=== RUN TestCompletedNarNotReofferedAcrossClosures774=== PAUSE TestCompletedNarNotReofferedAcrossClosures775=== RUN TestPresignedUploadRegisteredBeforeCommit776=== PAUSE TestPresignedUploadRegisteredBeforeCommit777=== RUN TestService_Rustfstest778=== PAUSE TestService_Rustfstest779=== RUN TestParseSize780=== PAUSE TestParseSize781=== RUN TestSkippedUploadsHandler782=== PAUSE TestSkippedUploadsHandler783=== RUN TestSystemdListenerNotActivated784--- PASS: TestSystemdListenerNotActivated (0.00s)785=== RUN TestWatchdogBeatsWhenHealthy786--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)787=== RUN TestWatchdogSkipsWhenUnhealthy7882026/11/10 21:11:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7892026/11/10 21:11:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7902026/11/10 21:11:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7912026/11/10 21:11:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7922026/11/10 21:11:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7932026/11/10 21:11:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7942026/11/10 21:11:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7952026/11/10 21:11:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7962026/11/10 21:11:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7972026/11/10 21:11:47 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"798--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)799=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle800=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle801=== RUN TestProxyWriteTimeout802=== PAUSE TestProxyWriteTimeout803=== RUN TestPendingClosureWriteTimeout804=== PAUSE TestPendingClosureWriteTimeout805=== RUN TestIsValidUploadKey806=== PAUSE TestIsValidUploadKey807=== RUN TestUploadHandlersRejectInvalidKeys808=== PAUSE TestUploadHandlersRejectInvalidKeys809=== RUN TestUploadHandlersRejectOversizedBody810=== PAUSE TestUploadHandlersRejectOversizedBody811=== RUN TestService_cleanupPendingClosuresHandler812=== PAUSE TestService_cleanupPendingClosuresHandler813=== RUN TestService_createPendingClosureHandler814=== PAUSE TestService_createPendingClosureHandler815=== RUN TestService_verifyS3Integrity816=== PAUSE TestService_verifyS3Integrity817=== RUN TestService_verifyS3ReuploadsStaleNarinfo818=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo819=== RUN TestCompleteMultipartUnregistered820=== PAUSE TestCompleteMultipartUnregistered821=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT822=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT823=== CONT TestReadProxyNarinfo824=== CONT TestFailedS3DeleteKeepsTombstone825=== CONT TestEnsureAbortUploadsRule826=== CONT TestService_healthCheckHandler827=== CONT TestGCTaskStore_ConflictDifferentParams828--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)829=== CONT TestClientFallsBackToClosures830=== CONT TestPushDedupSurvivesConcurrentGC831=== CONT TestRegisterCompletedObjectNeedsPendingRow832=== CONT TestAbortSucceeded833=== CONT TestGracefulShutdownDrainsInflight834=== CONT TestPresentNotReportedWhileGCDeletesClosure835=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale836=== CONT TestGenerateLandingPage837=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale838=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh839--- PASS: TestAbortSucceeded (0.00s)840=== CONT TestIsValidCachePath841=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection842=== RUN TestIsValidCachePath/narinfo843=== CONT TestGCSweepDeliversEachKeyOnce844=== PAUSE TestIsValidCachePath/narinfo845=== CONT TestTombstonedObjectOfferedWithoutWaiting846=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars847=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars848=== RUN TestIsValidCachePath/nar_zst849=== CONT TestGCSweepSkipsPendingObjects850=== CONT TestDeduplicatedObjectsRecordedAsPending851=== CONT TestParseSingleRange852=== CONT TestService_readinessHandler853=== RUN TestParseSingleRange/none854=== PAUSE TestParseSingleRange/none855=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT856=== CONT TestCompleteMultipartUnregistered857=== CONT TestService_verifyS3ReuploadsStaleNarinfo858=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed859=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed8602026/11/10 21:11:47 INFO Starting HTTP server address=127.0.0.1:52885861=== CONT TestService_verifyS3Integrity862=== CONT TestSweepSkipsRowsLockedByPush863=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh864=== CONT TestForceGCDuringPushOffersSweptObject865=== CONT TestService_createPendingClosureHandler866=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows867=== PAUSE TestIsValidCachePath/nar_zst868=== RUN TestParseSingleRange/unknown_unit869=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed870=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed871=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost872=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost873=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed874=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed875=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed876=== RUN TestIsValidCachePath/nar_xz877=== PAUSE TestIsValidCachePath/nar_xz878=== PAUSE TestParseSingleRange/unknown_unit879=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows880=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check881=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check882=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed883=== CONT TestService_cleanupPendingClosuresHandler884=== RUN TestIsValidCachePath/nar_bz2885=== PAUSE TestIsValidCachePath/nar_bz2886=== RUN TestIsValidCachePath/nar_uncompressed887=== PAUSE TestIsValidCachePath/nar_uncompressed888=== RUN TestIsValidCachePath/ls889=== PAUSE TestIsValidCachePath/ls890=== RUN TestIsValidCachePath/log891=== PAUSE TestIsValidCachePath/log892=== RUN TestParseSingleRange/multi-range_ignored893=== RUN TestIsValidCachePath/realisation894=== CONT TestPresentRefreshesOnlyStaleClosures895=== 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 TestIsValidCachePath/traversal_in_middle903=== PAUSE TestIsValidCachePath/traversal_in_middle904=== RUN TestIsValidCachePath/invalid_char_e905=== PAUSE TestIsValidCachePath/invalid_char_e906=== RUN TestIsValidCachePath/invalid_char_u907=== PAUSE TestIsValidCachePath/invalid_char_u908=== PAUSE TestParseSingleRange/multi-range_ignored909=== RUN TestIsValidCachePath/random_path9102026/11/10 21:11:47 INFO Shutdown signal received, draining in-flight requests timeout=10s911=== RUN TestParseSingleRange/malformed_no_dash912=== PAUSE TestIsValidCachePath/random_path913=== PAUSE TestParseSingleRange/malformed_no_dash914=== RUN TestIsValidCachePath/empty915=== RUN TestParseSingleRange/malformed_both_empty916=== PAUSE TestIsValidCachePath/empty917=== PAUSE TestParseSingleRange/malformed_both_empty918=== RUN TestParseSingleRange/malformed_end_before_start919=== PAUSE TestParseSingleRange/malformed_end_before_start920=== RUN TestParseSingleRange/closed921=== PAUSE TestParseSingleRange/closed922=== RUN TestParseSingleRange/open-ended923=== PAUSE TestParseSingleRange/open-ended924=== RUN TestParseSingleRange/end_clamped_to_size925=== PAUSE TestParseSingleRange/end_clamped_to_size926=== RUN TestIsValidCachePath/leading_slash927=== PAUSE TestIsValidCachePath/leading_slash928=== RUN TestParseSingleRange/suffix929=== PAUSE TestParseSingleRange/suffix930=== RUN TestParseSingleRange/suffix_exceeds_size931=== PAUSE TestParseSingleRange/suffix_exceeds_size932=== RUN TestParseSingleRange/single_byte933=== PAUSE TestParseSingleRange/single_byte934=== RUN TestParseSingleRange/start_past_EOF935=== PAUSE TestParseSingleRange/start_past_EOF936=== RUN TestParseSingleRange/start_far_past_EOF937=== PAUSE TestParseSingleRange/start_far_past_EOF938=== RUN TestIsValidCachePath/wrong_extension939=== PAUSE TestIsValidCachePath/wrong_extension940=== RUN TestIsValidCachePath/short_hash941=== PAUSE TestIsValidCachePath/short_hash942=== CONT TestUploadHandlersRejectOversizedBody943=== CONT TestPresentReportsOnlyClosureRoots944--- PASS: TestGenerateLandingPage (0.05s)945=== CONT TestUploadHandlersRejectInvalidKeys946=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info947=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info948=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal949=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal950=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key951=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key952=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key953=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key954=== CONT TestIsValidUploadKey955=== RUN TestIsValidUploadKey/narinfo956=== PAUSE TestIsValidUploadKey/narinfo957=== RUN TestIsValidUploadKey/nar_zst958=== PAUSE TestIsValidUploadKey/nar_zst959=== RUN TestIsValidUploadKey/nar_xz960=== PAUSE TestIsValidUploadKey/nar_xz961=== RUN TestIsValidUploadKey/nar_plain962=== PAUSE TestIsValidUploadKey/nar_plain963=== RUN TestIsValidUploadKey/listing964=== PAUSE TestIsValidUploadKey/listing965=== RUN TestIsValidUploadKey/build_log966=== PAUSE TestIsValidUploadKey/build_log967=== RUN TestIsValidUploadKey/build_log_home-manager_file968=== PAUSE TestIsValidUploadKey/build_log_home-manager_file969=== RUN TestIsValidUploadKey/build_log_plus_in_name970=== PAUSE TestIsValidUploadKey/build_log_plus_in_name971=== RUN TestIsValidUploadKey/build_log_question_mark972=== PAUSE TestIsValidUploadKey/build_log_question_mark973=== RUN TestIsValidUploadKey/build_log_equals974=== PAUSE TestIsValidUploadKey/build_log_equals975=== RUN TestIsValidUploadKey/realisation976=== PAUSE TestIsValidUploadKey/realisation977=== RUN TestIsValidUploadKey/realisation_plus_in_output978=== PAUSE TestIsValidUploadKey/realisation_plus_in_output979=== RUN TestIsValidUploadKey/nix-cache-info980=== PAUSE TestIsValidUploadKey/nix-cache-info981=== RUN TestIsValidUploadKey/index.html982=== PAUSE TestIsValidUploadKey/index.html983=== RUN TestIsValidUploadKey/narinfo_key,_nar_type984=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type985=== RUN TestIsValidUploadKey/nar_key,_narinfo_type986=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type987=== RUN TestIsValidUploadKey/listing_key,_narinfo_type988=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type989=== RUN TestIsValidUploadKey/traversal990=== PAUSE TestIsValidUploadKey/traversal991=== RUN TestIsValidUploadKey/traversal_nar992=== PAUSE TestIsValidUploadKey/traversal_nar993=== RUN TestIsValidUploadKey/absolute994=== PAUSE TestIsValidUploadKey/absolute995=== RUN TestIsValidUploadKey/empty_key996=== PAUSE TestIsValidUploadKey/empty_key997=== RUN TestIsValidUploadKey/unknown_type998=== PAUSE TestIsValidUploadKey/unknown_type999=== CONT TestCreatePin_ReservedPins1000=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1001=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1002=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1003=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1004=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1005=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1006=== CONT TestPendingClosureWriteTimeout1007=== RUN TestPendingClosureWriteTimeout/empty1008=== PAUSE TestPendingClosureWriteTimeout/empty1009=== RUN TestPendingClosureWriteTimeout/400_objects1010=== PAUSE TestPendingClosureWriteTimeout/400_objects1011=== RUN TestPendingClosureWriteTimeout/670k_objects1012=== PAUSE TestPendingClosureWriteTimeout/670k_objects1013=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1014=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1015=== CONT TestProxyWriteTimeout1016=== RUN TestProxyWriteTimeout/narinfo1017=== PAUSE TestProxyWriteTimeout/narinfo1018=== RUN TestProxyWriteTimeout/1_GiB_nar1019=== PAUSE TestProxyWriteTimeout/1_GiB_nar1020=== RUN TestProxyWriteTimeout/10_GiB_nar1021=== PAUSE TestProxyWriteTimeout/10_GiB_nar1022=== RUN TestProxyWriteTimeout/unknown_size1023=== PAUSE TestProxyWriteTimeout/unknown_size1024=== CONT TestOrphanedObjectsGCStressTest1025--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1026=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle10272026/11/10 21:11:47 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52888/oidc1028--- PASS: TestService_healthCheckHandler (0.81s)1029=== CONT TestOrphanedObjectsGC10302026/11/10 21:11:48 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1031--- PASS: TestReadProxyNarinfo (1.27s)1032=== CONT TestSkippedUploadsHandler10332026/11/10 21:11:48 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001034--- PASS: TestSkippedUploadsHandler (0.00s)1035=== CONT TestObjectStatsUpdatedOncePerCommit10362026/11/10 21:11:48 INFO Received uploads request method=POST path=/api/pending_closures1037--- PASS: TestDeduplicatedObjectsRecordedAsPending (1.43s)1038=== CONT TestParseSize1039--- PASS: TestParseSize (0.00s)1040=== CONT TestService_Rustfstest10412026/11/10 21:11:48 INFO Received uploads request method=POST path=/api/pending_closures10422026/11/10 21:11:48 INFO Aborted multipart uploads count=0 kept=010432026/11/10 21:11:48 WARN Force mode enabled - objects will be deleted immediately without grace period10442026/11/10 21:11:48 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."10452026/11/10 21:11:48 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1046--- PASS: TestFailedS3DeleteKeepsTombstone (1.97s)1047=== CONT TestPresignedUploadRegisteredBeforeCommit10482026/11/10 21:11:49 INFO Received uploads request method=POST path=/api/pending_closures10492026/11/10 21:11:49 INFO Aborted multipart uploads count=0 kept=010502026/11/10 21:11:49 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=010512026/11/10 21:11:49 INFO Vacuumed table table=pending_closures10522026/11/10 21:11:49 INFO Vacuumed table table=pending_objects10532026/11/10 21:11:49 INFO Vacuumed table table=multipart_uploads10542026/11/10 21:11:49 INFO Vacuumed table table=closures10552026/11/10 21:11:49 INFO Vacuumed table table=objects10562026/11/10 21:11:49 INFO Aborted multipart uploads count=0 kept=010572026/11/10 21:11:49 WARN Force mode enabled - objects will be deleted immediately without grace period10582026/11/10 21:11:49 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket9 days=210592026/11/10 21:11:49 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01060--- PASS: TestEnsureAbortUploadsRule (2.33s)1061=== CONT TestCompletedNarNotReofferedAcrossClosures10622026/11/10 21:11:49 INFO Vacuumed table table=pending_closures10632026/11/10 21:11:49 INFO Vacuumed table table=pending_objects10642026/11/10 21:11:49 INFO Vacuumed table table=multipart_uploads10652026/11/10 21:11:49 INFO Vacuumed table table=closures10662026/11/10 21:11:49 INFO Vacuumed table table=objects1067--- PASS: TestPushDedupSurvivesConcurrentGC (2.35s)1068=== CONT TestCompleteMultipartUpload_ErrorButObjectExists10692026/11/10 21:11:49 INFO Received uploads request method=POST path=/api/pending_closures1070--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.67s)1071=== CONT TestSharedNarBothUploadsComplete10722026/11/10 21:11:49 INFO Received uploads request method=POST path=/api/pending_closures10732026/11/10 21:11:49 INFO Received uploads request method=POST path=/api/pending_closures10742026/11/10 21:11:49 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)10752026/11/10 21:11:49 INFO Uploading zdfw97x2l5lyagq4x1mz1iydac7iw18x-b (256B)10762026/11/10 21:11:49 INFO Uploading iq3knxszswy52phll1p6k4i8nc0dvvsn-shared-dep (136B)10772026/11/10 21:11:49 INFO Received uploads request method=POST path=/api/pending_closures10782026/11/10 21:11:49 WARN Failed to register uploaded object key=zdfw97x2l5lyagq4x1mz1iydac7iw18x.ls error="server returned 404: 404 page not found\n"10792026/11/10 21:11:49 WARN Failed to register uploaded object key=3vv5d631dagi7dh4kvjdfa3d80jr00h2.ls error="server returned 404: 404 page not found\n"10802026/11/10 21:11:49 WARN Failed to register uploaded object key=iq3knxszswy52phll1p6k4i8nc0dvvsn.ls error="server returned 404: 404 page not found\n"10812026/11/10 21:11:49 WARN Failed to register uploaded object key=nar/1nyd2j2c0286pczqjb5ircp4blwwj7rwdnad322vmsf4y96547ma.nar.zst error="server returned 404: 404 page not found\n"10822026/11/10 21:11:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign10832026/11/10 21:11:49 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"10842026/11/10 21:11:49 INFO Signed narinfos id=1 count=210852026/11/10 21:11:49 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign10862026/11/10 21:11:49 INFO Signed narinfos id=2 count=210872026/11/10 21:11:49 INFO Uploading 4 narinfos10882026/11/10 21:11:49 WARN Failed to register uploaded object key=3vv5d631dagi7dh4kvjdfa3d80jr00h2.narinfo error="server returned 404: 404 page not found\n"10892026/11/10 21:11:49 WARN Failed to register uploaded object key=zdfw97x2l5lyagq4x1mz1iydac7iw18x.narinfo error="server returned 404: 404 page not found\n"10902026/11/10 21:11:49 WARN Failed to register uploaded object key=iq3knxszswy52phll1p6k4i8nc0dvvsn.narinfo error="server returned 404: 404 page not found\n"10912026/11/10 21:11:49 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10922026/11/10 21:11:49 WARN Failed to register uploaded object key=iq3knxszswy52phll1p6k4i8nc0dvvsn.narinfo error="server returned 404: 404 page not found\n"10932026/11/10 21:11:50 INFO Completed upload id=1 objects=6 duration=14.270042ms10942026/11/10 21:11:50 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10952026/11/10 21:11:50 INFO Completed upload id=2 objects=6 duration=510µs10962026/11/10 21:11:50 INFO Upload complete. (261ms)1097=== NAME TestClientFallsBackToClosures1098 client_pushes_test.go:112: Retrieved narinfo from S3:1099 StorePath: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientFallsBackToClosures3297455673/001/store/iq3knxszswy52phll1p6k4i8nc0dvvsn-shared-dep1100 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1101 Compression: zstd1102 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821103 NarSize: 1361104 References: 1105 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1106 client_pushes_test.go:112: Retrieved narinfo from S3:1107 StorePath: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientFallsBackToClosures3297455673/001/store/3vv5d631dagi7dh4kvjdfa3d80jr00h2-a1108 URL: nar/1nyd2j2c0286pczqjb5ircp4blwwj7rwdnad322vmsf4y96547ma.nar.zst1109 Compression: zstd1110 NarHash: sha256:1nyd2j2c0286pczqjb5ircp4blwwj7rwdnad322vmsf4y96547ma1111 NarSize: 2561112 References: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientFallsBackToClosures3297455673/001/store/iq3knxszswy52phll1p6k4i8nc0dvvsn-shared-dep1113 CA: text:sha256:1bzknqkl270ljr01pmgk2vpkba1n839xr2827mm8fxvixd4xlnkd1114 client_pushes_test.go:112: Retrieved narinfo from S3:1115 StorePath: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientFallsBackToClosures3297455673/001/store/zdfw97x2l5lyagq4x1mz1iydac7iw18x-b1116 URL: nar/1nyd2j2c0286pczqjb5ircp4blwwj7rwdnad322vmsf4y96547ma.nar.zst1117 Compression: zstd1118 NarHash: sha256:1nyd2j2c0286pczqjb5ircp4blwwj7rwdnad322vmsf4y96547ma1119 NarSize: 2561120 References: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientFallsBackToClosures3297455673/001/store/iq3knxszswy52phll1p6k4i8nc0dvvsn-shared-dep1121 CA: text:sha256:1bzknqkl270ljr01pmgk2vpkba1n839xr2827mm8fxvixd4xlnkd1122--- PASS: TestClientFallsBackToClosures (3.02s)1123=== CONT TestPush_SignsNarinfosOfItsPendingObjects1124--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (3.07s)1125=== CONT TestPush_RejectsBadRequests11262026/11/10 21:11:50 INFO Aborted multipart uploads count=0 kept=011272026/11/10 21:11:50 WARN Force mode enabled - objects will be deleted immediately without grace period11282026/11/10 21:11:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011292026/11/10 21:11:50 INFO Vacuumed table table=pending_closures11302026/11/10 21:11:50 INFO Vacuumed table table=pending_objects11312026/11/10 21:11:50 INFO Vacuumed table table=multipart_uploads11322026/11/10 21:11:50 INFO Vacuumed table table=closures11332026/11/10 21:11:50 INFO Vacuumed table table=objects11342026/11/10 21:11:50 INFO Aborted multipart uploads count=0 kept=011352026/11/10 21:11:50 WARN Force mode enabled - objects will be deleted immediately without grace period1136--- PASS: TestPresentRefreshesOnlyStaleClosures (3.29s)1137=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit11382026/11/10 21:11:50 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=011392026/11/10 21:11:50 INFO Vacuumed table table=pending_closures11402026/11/10 21:11:50 INFO Vacuumed table table=pending_objects11412026/11/10 21:11:50 INFO Vacuumed table table=multipart_uploads11422026/11/10 21:11:50 INFO Vacuumed table table=closures11432026/11/10 21:11:50 INFO Vacuumed table table=objects1144--- PASS: TestSweepSkipsRowsLockedByPush (3.34s)1145=== CONT TestPush_RootsAreLockedInByteOrder11462026/11/10 21:11:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11472026/11/10 21:11:50 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1148--- PASS: TestCompleteMultipartUnregistered (3.43s)1149=== CONT TestPush_CompleteWaitsForCleanupOfThePush11502026/11/10 21:11:50 INFO Received cleanup request method=DELETE path=/api/pending_closures11512026/11/10 21:11:50 INFO Aborted multipart uploads count=0 kept=011522026/11/10 21:11:50 INFO Received uploads request method=POST path=/api/pending_closures11532026/11/10 21:11:50 INFO Received cleanup request method=DELETE path=/api/pending_closures11542026/11/10 21:11:50 INFO Aborted multipart uploads count=1 kept=011552026/11/10 21:11:50 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11562026-11-10 21:11:50.709 UTC [91047] ERROR: Closure does not exist: id=111572026-11-10 21:11:50.709 UTC [91047] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE11582026-11-10 21:11:50.709 UTC [91047] STATEMENT: -- name: CommitPendingClosure :one1159 SELECT commit_pending_closure($1::bigint)::bigint1160 1161--- PASS: TestService_cleanupPendingClosuresHandler (3.68s)1162=== CONT TestPush_RepeatedRootCommitsOnce1163--- PASS: TestRegisterCompletedObjectNeedsPendingRow (3.76s)1164=== CONT TestPush_CompleteCommitsEveryRoot11652026/11/10 21:11:50 WARN readiness check failed error="closed pool"1166--- PASS: TestService_readinessHandler (3.92s)1167=== CONT TestPush_OverlappingRootsStoreOneRowPerKey11682026/11/10 21:11:51 INFO Aborted multipart uploads count=0 kept=011692026/11/10 21:11:51 WARN Force mode enabled - objects will be deleted immediately without grace period11702026/11/10 21:11:51 INFO Received uploads request method=POST path=/api/pending_closures11712026/11/10 21:11:51 INFO Received uploads request method=POST path=/api/pending_closures11722026/11/10 21:11:51 INFO Received uploads request method=POST path=/api/pending_closures11732026/11/10 21:11:51 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=011742026/11/10 21:11:51 INFO Vacuumed table table=pending_closures11752026/11/10 21:11:51 INFO Vacuumed table table=pending_objects11762026/11/10 21:11:51 INFO Vacuumed table table=multipart_uploads11772026/11/10 21:11:51 INFO Vacuumed table table=closures11782026/11/10 21:11:51 INFO Received uploads request method=POST path=/api/pending_closures11792026/11/10 21:11:51 INFO Vacuumed table table=objects1180--- PASS: TestGCSweepDeliversEachKeyOnce (4.76s)1181=== CONT TestReadRedirectUsesPublicS3URL1182--- PASS: TestTombstonedObjectOfferedWithoutWaiting (4.78s)1183=== CONT TestReadProxyRangeRequest11842026/11/10 21:11:51 INFO Received uploads request method=POST path=/api/pending_closures11852026/11/10 21:11:52 INFO Received uploads request method=POST path=/api/pending_closures11862026/11/10 21:11:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11872026/11/10 21:11:52 INFO Aborted multipart uploads count=0 kept=011882026/11/10 21:11:52 WARN Force mode enabled - objects will be deleted immediately without grace period11892026/11/10 21:11:52 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=011902026/11/10 21:11:52 INFO Vacuumed table table=pending_closures11912026/11/10 21:11:52 INFO Vacuumed table table=pending_objects11922026/11/10 21:11:52 INFO Vacuumed table table=multipart_uploads11932026/11/10 21:11:52 INFO Vacuumed table table=closures11942026/11/10 21:11:52 INFO Vacuumed table table=objects1195--- PASS: TestGCSweepSkipsPendingObjects (5.53s)1196=== CONT TestReadRedirectKeepsNarinfoProxied1197--- PASS: TestPresentReportsOnlyClosureRoots (5.62s)1198=== CONT TestObjectStatsTrigger11992026/11/10 21:11:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12002026/11/10 21:11:53 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLjNiYTEzY2YzLTQyNDctNDJlMC05MjAxLWVmNTE1NzgwZGU2YngxNzk0MzQ1MTExNDU3MjAxMDAw parts=1012012026/11/10 21:11:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12022026/11/10 21:11:53 INFO Completed upload id=1 objects=2 duration=16.3915ms12032026/11/10 21:11:53 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000012042026/11/10 21:11:53 INFO Received uploads request method=POST path=/api/pending_closures12052026/11/10 21:11:53 INFO Starting cleanup of old closures method=DELETE path=/api/closures12062026/11/10 21:11:53 INFO Aborted multipart uploads count=0 kept=012072026/11/10 21:11:53 INFO Received uploads request method=POST path=/api/pending_closures12082026/11/10 21:11:53 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=012092026/11/10 21:11:53 INFO Vacuumed table table=pending_closures12102026/11/10 21:11:53 INFO Vacuumed table table=pending_objects12112026/11/10 21:11:53 INFO Vacuumed table table=multipart_uploads12122026/11/10 21:11:53 INFO Vacuumed table table=closures12132026/11/10 21:11:53 INFO Vacuumed table table=objects12142026/11/10 21:11:53 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001215--- PASS: TestService_createPendingClosureHandler (6.21s)1216=== CONT TestReadRedirectNar12172026/11/10 21:11:53 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12182026/11/10 21:11:53 WARN Refused reserved pin name=worker-x86_64-linux12192026/11/10 21:11:53 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12202026/11/10 21:11:53 INFO Received create pin request method=POST path=/api/pins/my-app12212026/11/10 21:11:53 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1222--- PASS: TestCreatePin_ReservedPins (6.33s)1223=== CONT TestPendingCleanupUsesOneCutoff1224--- PASS: TestService_Rustfstest (5.45s)1225=== CONT TestReadProxyDisabled1226--- PASS: TestObjectStatsUpdatedOncePerCommit (6.35s)1227=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded12282026/11/10 21:11:54 INFO Received uploads request method=POST path=/api/pending_closures12292026/11/10 21:11:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12302026/11/10 21:11:54 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLmUzYTUwYjdiLTNiNzYtNGZkNy05ODkxLTQ2ZTQ3ZTQ5ZTM5ZXgxNzk0MzQ1MTEzMTM1MDE1MDAw parts=1012312026/11/10 21:11:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12322026/11/10 21:11:54 INFO Completed upload id=1 objects=2 duration=48.928417ms12332026/11/10 21:11:54 INFO Received uploads request method=POST path=/api/pending_closures12342026/11/10 21:11:55 INFO Received uploads request method=POST path=/api/pending_closures12352026/11/10 21:11:55 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo12362026/11/10 21:11:55 WARN Found objects in DB but missing from S3, will re-upload count=11237--- PASS: TestService_verifyS3Integrity (7.98s)1238=== CONT TestMultipartCleanup12392026/11/10 21:11:55 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst12402026/11/10 21:11:55 INFO Received uploads request method=POST path=/api/pending_closures1241--- PASS: TestPresignedUploadRegisteredBeforeCommit (6.11s)1242=== CONT TestReadProxyRootRedirectsToIndexHTML12432026/11/10 21:11:55 INFO Received uploads request method=POST path=/api/pending_closures12442026/11/10 21:11:55 INFO Received uploads request method=POST path=/api/pending_closures1245=== NAME TestOrphanedObjectsGC1246 orphaned_objects_gc_test.go:287: GC Test Summary:1247 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1248 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1249 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1250 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1251 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1252--- PASS: TestOrphanedObjectsGC (8.35s)1253=== CONT TestReadProxyConditionalGet12542026/11/10 21:11:56 WARN Rate limiter enabled after throttle name=s3-test rate=512552026/11/10 21:11:56 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1256=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1257 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101258 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001259--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (9.28s)1260=== CONT TestReadProxyOutlastsServerWriteTimeout12612026/11/10 21:11:56 INFO Received uploads request method=POST path=/api/pending_closures12622026/11/10 21:11:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12632026/11/10 21:11:56 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLjZhYzczYzY4LTZhZDYtNDBhMC04ZDc5LWRmMjNjMzUyOGZjOXgxNzk0MzQ1MTE1OTY1NzQ2MDAw12642026/11/10 21:11:56 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLjZhYzczYzY4LTZhZDYtNDBhMC04ZDc5LWRmMjNjMzUyOGZjOXgxNzk0MzQ1MTE1OTY1NzQ2MDAw parts=11265--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (7.21s)1266=== CONT TestReadProxyHead12672026/11/10 21:11:56 INFO Received uploads request method=POST path=/api/pending_closures1268=== RUN TestPush_RejectsBadRequests/no_objects1269=== PAUSE TestPush_RejectsBadRequests/no_objects1270=== RUN TestPush_RejectsBadRequests/bad_root1271=== PAUSE TestPush_RejectsBadRequests/bad_root1272=== RUN TestPush_RejectsBadRequests/root_not_in_objects1273=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1274=== RUN TestPush_RejectsBadRequests/no_roots1275=== PAUSE TestPush_RejectsBadRequests/no_roots1276=== CONT TestReadProxyInvalidPath12772026/11/10 21:11:57 INFO Received push request method=POST path=/api/pushes12782026/11/10 21:11:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12792026/11/10 21:11:57 INFO Signed narinfos id=1 count=112802026/11/10 21:11:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12812026/11/10 21:11:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12822026/11/10 21:11:57 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"12832026/11/10 21:11:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12842026/11/10 21:11:57 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"12852026/11/10 21:11:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12862026/11/10 21:11:57 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=112872026/11/10 21:11:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12882026/11/10 21:11:57 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1289--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (7.55s)1290=== CONT TestReadProxy40412912026/11/10 21:11:57 INFO Received push request method=POST path=/api/pushes12922026/11/10 21:11:58 INFO Received complete push request method=POST path=/api/pushes/1/complete12932026/11/10 21:11:58 INFO Completed push id=1 objects=4 duration=46.070917ms12942026/11/10 21:11:58 INFO Received push request method=POST path=/api/pushes12952026/11/10 21:11:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12962026/11/10 21:11:58 INFO Aborted multipart uploads count=0 kept=012972026/11/10 21:11:58 WARN Force mode enabled - objects will be deleted immediately without grace period12982026/11/10 21:11:58 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=012992026/11/10 21:11:58 INFO Received push request method=POST path=/api/pushes13002026/11/10 21:11:58 INFO Vacuumed table table=pending_closures13012026/11/10 21:11:58 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLjdjM2M5MTRmLTI4ZGQtNDJjZS05MzVmLTEwZDYxYWNhZTM3MngxNzk0MzQ1MTE1MzIxOTIxMDAw parts=1213022026/11/10 21:11:58 INFO Received uploads request method=POST path=/api/pending_closures1303--- PASS: TestCompletedNarNotReofferedAcrossClosures (9.12s)1304=== CONT TestReadProxyNarStreaming13052026/11/10 21:11:58 INFO Vacuumed table table=pending_objects13062026/11/10 21:11:58 INFO Vacuumed table table=multipart_uploads13072026/11/10 21:11:58 INFO Vacuumed table table=closures13082026/11/10 21:11:58 INFO Vacuumed table table=objects13092026/11/10 21:11:58 INFO Received complete push request method=POST path=/api/pushes/2/complete13102026-11-10 21:11:58.682 UTC [91159] ERROR: could not obtain lock on row in relation "closures"13112026-11-10 21:11:58.682 UTC [91159] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13122026-11-10 21:11:58.688 UTC [91159] ERROR: could not obtain lock on row in relation "closures"13132026-11-10 21:11:58.688 UTC [91159] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13142026-11-10 21:11:58.690 UTC [91159] ERROR: could not obtain lock on row in relation "closures"13152026-11-10 21:11:58.690 UTC [91159] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13162026/11/10 21:11:58 INFO Completed push id=2 objects=4 duration=18.88525ms13172026-11-10 21:11:58.700 UTC [91159] ERROR: could not obtain lock on row in relation "closures"13182026-11-10 21:11:58.700 UTC [91159] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13192026-11-10 21:11:58.707 UTC [91159] ERROR: could not obtain lock on row in relation "closures"13202026-11-10 21:11:58.707 UTC [91159] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1321--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (8.38s)1322=== CONT TestReadProxyContentNegotiation1323--- PASS: TestPush_RootsAreLockedInByteOrder (8.36s)1324=== CONT TestReadProxyNarinfoAlreadyDecompressed13252026/11/10 21:11:58 INFO Received push request method=POST path=/api/pushes13262026/11/10 21:11:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13272026/11/10 21:11:59 INFO Received push request method=POST path=/api/pushes13282026-11-10 21:11:59.288 UTC [91165] ERROR: Push does not exist: id=113292026-11-10 21:11:59.288 UTC [91165] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE13302026-11-10 21:11:59.288 UTC [91165] STATEMENT: SELECT commit_push($1)1331--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (8.84s)1332=== CONT TestServerTLSConfig1333=== RUN TestServerTLSConfig/no_client_CA1334=== PAUSE TestServerTLSConfig/no_client_CA1335=== RUN TestServerTLSConfig/missing_CA_file1336=== PAUSE TestServerTLSConfig/missing_CA_file1337=== RUN TestServerTLSConfig/not_a_PEM_file1338=== PAUSE TestServerTLSConfig/not_a_PEM_file1339=== CONT TestNARDeduplicationMetadataUploadBug13402026/11/10 21:11:59 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLjViNTY4Y2Q0LWI2MTAtNDM2NC1hYTY4LWRjY2VkMmQ5ZWIxMHgxNzk0MzQ1MTE2NTcwMDkyMDAw parts=1213412026/11/10 21:11:59 INFO Received complete push request method=POST path=/api/pushes/1/complete13422026/11/10 21:11:59 INFO Completed push id=1 objects=4 duration=71.593667ms1343--- PASS: TestPush_RepeatedRootCommitsOnce (8.78s)1344=== CONT TestCreatePendingClosureRejectsOversizedNAR13452026/11/10 21:11:59 INFO Received uploads request method=POST path=/api/pending_closures1346--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1347=== CONT TestCacheConfigHandlerMaxNarSize1348--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1349=== CONT TestMetricsInventory13502026/11/10 21:11:59 INFO Received push request method=POST path=/api/pushes13512026/11/10 21:11:59 INFO Received complete push request method=POST path=/api/pushes/1/complete13522026/11/10 21:11:59 INFO Completed push id=1 objects=6 duration=52.845375ms1353--- PASS: TestPush_CompleteCommitsEveryRoot (9.13s)1354=== CONT TestService_NativeMTLS13552026/11/10 21:12:00 INFO Received push request method=POST path=/api/pushes1356--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (9.36s)1357=== CONT TestMetricsCommit1358--- PASS: TestReadRedirectUsesPublicS3URL (8.84s)1359=== CONT TestLeadIncumbentAnnouncesAtOnce1360--- PASS: TestReadProxyRangeRequest (9.25s)1361=== CONT TestGCMetrics1362--- PASS: TestReadRedirectKeepsNarinfoProxied (8.86s)1363=== CONT TestGCBugBareHashReferences13642026/11/10 21:12:01 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13652026/11/10 21:12:01 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLjQ4YWQwODBlLTUzNjctNDhkOC1hMWUyLTNmZjdkMDAwZTRlM3gxNzk0MzQ1MTE2NjUxOTM2MDAw parts=121366--- PASS: TestSharedNarBothUploadsComplete (12.07s)1367=== CONT TestGCAdvisoryLockBlocksConcurrentRun1368--- PASS: TestObjectStatsTrigger (9.21s)1369=== CONT TestLeadEndsOnShutdown1370--- PASS: TestReadRedirectNar (8.88s)1371=== CONT TestGCTaskStore_CompletedAllowsNewTask1372--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1373=== CONT TestGCTaskStore_Fail1374--- PASS: TestGCTaskStore_Fail (0.00s)1375=== CONT TestGCTaskStore_PhaseUpdates1376--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1377=== CONT TestCacheStatsHandler13782026/11/10 21:12:02 INFO Received uploads request method=POST path=/api/pending_closures13792026/11/10 21:12:02 INFO Received uploads request method=POST path=/api/pending_closures13802026/11/10 21:12:02 INFO Received cleanup request method=DELETE path=/api/pending_closures1381--- PASS: TestReadProxyDisabled (8.86s)1382=== CONT TestClientPushesUseOnePush13832026/11/10 21:12:03 INFO Received uploads request method=POST path=/api/pending_closures1384--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (8.70s)1385=== CONT TestPinProtectsFromGC13862026/11/10 21:12:03 INFO Received uploads request method=POST path=/api/pending_closures13872026/11/10 21:12:03 INFO Received cleanup request method=DELETE path=/api/pending_closures13882026/11/10 21:12:03 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket51/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""13892026/11/10 21:12:03 INFO Aborted multipart uploads count=0 kept=113902026/11/10 21:12:03 INFO Received cleanup request method=DELETE path=/api/pending_closures13912026/11/10 21:12:03 INFO Aborted multipart uploads count=1 kept=01392--- PASS: TestMultipartCleanup (8.80s)1393=== CONT TestClientSharedPathCommittedMidPush1394--- PASS: TestReadProxyRootRedirectsToIndexHTML (8.84s)1395=== CONT TestClientWithDependencies1396--- PASS: TestReadProxyConditionalGet (8.48s)1397=== CONT TestResolveDBConnectionString1398=== RUN TestResolveDBConnectionString/flag_wins1399=== PAUSE TestResolveDBConnectionString/flag_wins1400=== RUN TestResolveDBConnectionString/file_when_flag_empty1401=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1402=== RUN TestResolveDBConnectionString/missing_file_is_an_error1403=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1404=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1405=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1406=== RUN TestResolveDBConnectionString/nothing_configured1407=== PAUSE TestResolveDBConnectionString/nothing_configured1408=== CONT TestClientMultipleUploads1409--- PASS: TestReadProxyHead (8.40s)1410=== CONT TestLeadElectsOneAndHandsOver1411--- PASS: TestReadProxyInvalidPath (8.26s)1412=== CONT TestClientIntegration1413--- PASS: TestReadProxyNarinfoAlreadyDecompressed (7.33s)1414=== CONT TestConnectWaitsForAPeerMigration1415--- PASS: TestReadProxy404 (8.76s)1416=== CONT TestClientErrorHandling1417=== RUN TestClientErrorHandling/InvalidStorePath1418=== PAUSE TestClientErrorHandling/InvalidStorePath1419=== RUN TestClientErrorHandling/InvalidAuthToken1420=== PAUSE TestClientErrorHandling/InvalidAuthToken1421=== RUN TestClientErrorHandling/ServerNotAvailable1422=== PAUSE TestClientErrorHandling/ServerNotAvailable1423=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1424--- PASS: TestReadProxyNarStreaming (8.05s)1425=== CONT TestClientCADerivations1426--- PASS: TestReadProxyContentNegotiation (8.35s)1427=== CONT TestDeleteClosuresRacingPins1428=== NAME TestNARDeduplicationMetadataUploadBug1429 metadata_upload_test.go:48: First store path: /private/var/tb/6/scratch/509dce1726107d78/build/TestNARDeduplicationMetadataUploadBug3685875544/001/store/4rmyrlj3fmanhnv2005495vii8n0bqkp-file1.txt1430--- PASS: TestMetricsInventory (8.17s)1431=== CONT TestService_ReadScope_PublicByDefault14322026/11/10 21:12:07 INFO Received push request method=POST path=/api/pushes14332026/11/10 21:12:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14342026/11/10 21:12:07 INFO Uploading 4rmyrlj3fmanhnv2005495vii8n0bqkp-file1.txt (160B)14352026/11/10 21:12:07 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"14362026/11/10 21:12:07 WARN mTLS auth: subject not in bound subjects subject="CN=reader"14372026/11/10 21:12:07 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1438--- PASS: TestService_NativeMTLS (8.02s)1439=== CONT TestCacheConfigHandler1440=== RUN TestCacheConfigHandler/full_config,_no_issuer1441=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1442=== RUN TestCacheConfigHandler/no_cache_url_configured1443=== PAUSE TestCacheConfigHandler/no_cache_url_configured1444=== RUN TestCacheConfigHandler/no_signing_keys1445=== PAUSE TestCacheConfigHandler/no_signing_keys1446=== RUN TestCacheConfigHandler/upstream_keys_advertised1447=== PAUSE TestCacheConfigHandler/upstream_keys_advertised1448=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1449=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1450=== CONT TestService_AuthMiddleware_OIDC14512026/11/10 21:12:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14522026/11/10 21:12:07 WARN Failed to register uploaded object key=4rmyrlj3fmanhnv2005495vii8n0bqkp.ls error="server returned 404: 404 page not found\n"14532026/11/10 21:12:07 INFO Signed narinfos id=1 count=114542026/11/10 21:12:07 INFO Uploading 1 narinfos14552026/11/10 21:12:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53117/oidc14562026/11/10 21:12:08 INFO Received complete push request method=POST path=/api/pushes/1/complete14572026/11/10 21:12:08 WARN Failed to register uploaded object key=4rmyrlj3fmanhnv2005495vii8n0bqkp.narinfo error="server returned 404: 404 page not found\n"1458=== NAME TestOrphanedObjectsGCStressTest1459 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains14602026/11/10 21:12:08 INFO Completed push id=1 objects=3 duration=36.018333ms14612026/11/10 21:12:08 INFO Upload complete. (333ms)1462=== NAME TestNARDeduplicationMetadataUploadBug1463 metadata_upload_test.go:54: Retrieved narinfo from S3:1464 StorePath: /private/var/tb/6/scratch/509dce1726107d78/build/TestNARDeduplicationMetadataUploadBug3685875544/001/store/4rmyrlj3fmanhnv2005495vii8n0bqkp-file1.txt1465 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1466 Compression: zstd1467 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1468 NarSize: 1601469 References: 1470 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1471 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1472 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1473 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1474=== NAME TestOrphanedObjectsGCStressTest1475 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1476=== NAME TestNARDeduplicationMetadataUploadBug1477 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/6/scratch/509dce1726107d78/build/TestNARDeduplicationMetadataUploadBug3685875544/001/store/sa4fwfmblzn3jzhhac78x4mq4xrs0m6x-file2.txt14782026/11/10 21:12:08 INFO Received push request method=POST path=/api/pushes14792026/11/10 21:12:08 INFO Received push request method=POST path=/api/pushes14802026/11/10 21:12:08 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14812026/11/10 21:12:08 INFO Received complete push request method=POST path=/api/pushes/1/complete14822026/11/10 21:12:08 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14832026/11/10 21:12:08 WARN Failed to register uploaded object key=sa4fwfmblzn3jzhhac78x4mq4xrs0m6x.ls error="server returned 404: 404 page not found\n"14842026/11/10 21:12:08 INFO Signed narinfos id=2 count=114852026/11/10 21:12:08 INFO Uploading 1 narinfos14862026/11/10 21:12:08 INFO Completed push id=1 objects=4 duration=60.088541ms14872026/11/10 21:12:08 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14882026/11/10 21:12:08 INFO Completed upload id=2 objects=2 duration=607.917µs1489--- PASS: TestMetricsCommit (8.21s)1490=== CONT TestService_RequireScope_OIDC14912026/11/10 21:12:08 INFO Received complete push request method=POST path=/api/pushes/2/complete14922026/11/10 21:12:08 WARN Failed to register uploaded object key=sa4fwfmblzn3jzhhac78x4mq4xrs0m6x.narinfo error="server returned 404: 404 page not found\n"14932026/11/10 21:12:08 INFO Completed push id=2 objects=3 duration=894.708µs14942026/11/10 21:12:08 INFO Upload complete. (240ms)1495=== NAME TestNARDeduplicationMetadataUploadBug1496 metadata_upload_test.go:76: Retrieved narinfo from S3:1497 StorePath: /private/var/tb/6/scratch/509dce1726107d78/build/TestNARDeduplicationMetadataUploadBug3685875544/001/store/sa4fwfmblzn3jzhhac78x4mq4xrs0m6x-file2.txt1498 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1499 Compression: zstd1500 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1501 NarSize: 1601502 References: 1503 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1504 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1505 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1506 {"version":1,"root":{"type":"regular","size":44}}1507--- PASS: TestReadProxyOutlastsServerWriteTimeout (12.20s)1508=== CONT TestService_AuthMiddleware_MTLSBoundSubjects15092026/11/10 21:12:08 INFO Aborted multipart uploads count=1 kept=015102026/11/10 21:12:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53128/oidc15112026/11/10 21:12:08 INFO Received cleanup request method=DELETE path=/api/pending_closures15122026/11/10 21:12:08 INFO Aborted multipart uploads count=1 kept=01513--- PASS: TestPendingCleanupUsesOneCutoff (15.28s)1514=== CONT TestService_ReadAuthMiddleware1515--- PASS: TestNARDeduplicationMetadataUploadBug (9.41s)1516=== CONT TestService_AuthMiddleware_MTLSProxyHeader15172026/11/10 21:12:08 INFO lead: acquired remote=192.0.2.1:123415182026/11/10 21:12:08 INFO lead: released remote=192.0.2.1:12341519--- PASS: TestLeadIncumbentAnnouncesAtOnce (8.10s)1520=== CONT TestSweepRechecksPendingAfterLocking15212026/11/10 21:12:09 INFO Aborted multipart uploads count=0 kept=015222026/11/10 21:12:09 WARN Force mode enabled - objects will be deleted immediately without grace period15232026/11/10 21:12:09 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=015242026/11/10 21:12:09 INFO Vacuumed table table=pending_closures15252026/11/10 21:12:09 INFO Vacuumed table table=pending_objects15262026/11/10 21:12:09 INFO Vacuumed table table=multipart_uploads15272026/11/10 21:12:09 INFO Vacuumed table table=closures15282026/11/10 21:12:09 INFO Vacuumed table table=objects1529--- PASS: TestGCMetrics (8.36s)1530=== CONT TestCommitRacingPendingCleanupKeepsObjects1531--- PASS: TestGCBugBareHashReferences (8.62s)1532=== CONT TestGCTaskStore_GetEmpty1533--- PASS: TestGCTaskStore_GetEmpty (0.00s)1534=== CONT TestPushWaitsForSweepHoldingRow15352026/11/10 21:12:10 INFO lead: acquired remote=192.0.2.1:123415362026/11/10 21:12:10 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld6 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1537--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (8.76s)1538=== CONT TestGCTaskStore_DeduplicateSameParams1539--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1540=== CONT TestGCTaskStore_GetReturnsLatest1541--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1542=== CONT TestService_AuthMiddleware1543--- PASS: TestCacheStatsHandler (8.89s)1544=== CONT TestGCTaskStore_StartNew1545--- PASS: TestGCTaskStore_StartNew (0.00s)1546=== CONT TestGCEndsOnShutdown1547=== RUN TestGCEndsOnShutdown/before_the_run1548=== PAUSE TestGCEndsOnShutdown/before_the_run1549=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1550=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1551=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1552=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1553=== CONT TestGetExistingObjectsLocksRows15542026/11/10 21:12:11 INFO lead: released remote=192.0.2.1:12341555--- PASS: TestLeadEndsOnShutdown (9.29s)1556=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale15572026/11/10 21:12:12 INFO Received push request method=POST path=/api/pushes15582026/11/10 21:12:12 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15592026/11/10 21:12:12 INFO Uploading qqlfscn7930dy105fkz7d8rq1m58bjxv-a (256B)15602026/11/10 21:12:12 INFO Uploading zp9f62avvbwwj4sw9393iy0qgbr68cy7-shared-dep (136B)1561=== NAME TestPinProtectsFromGC1562 client_integration_test.go:778: Pinned store path: /private/var/tb/6/scratch/509dce1726107d78/build/TestPinProtectsFromGC3535349557/001/store/ya1dljwx0jlq6151vlgfpf1ygpbnqs1g-pinned-file.txt1563 client_integration_test.go:779: Unpinned store path: /private/var/tb/6/scratch/509dce1726107d78/build/TestPinProtectsFromGC3535349557/001/store/fzv9fkr3f37dyqzj71ng2wkjx48q2fx4-unpinned-file.txt15642026/11/10 21:12:12 WARN Failed to register uploaded object key=0vwdlk7dy9cir5359q732izcyg2db8ln.ls error="server returned 404: 404 page not found\n"15652026/11/10 21:12:12 WARN Failed to register uploaded object key=zp9f62avvbwwj4sw9393iy0qgbr68cy7.ls error="server returned 404: 404 page not found\n"15662026/11/10 21:12:12 WARN Failed to register uploaded object key=qqlfscn7930dy105fkz7d8rq1m58bjxv.ls error="server returned 404: 404 page not found\n"15672026/11/10 21:12:12 WARN Failed to register uploaded object key=nar/13ypvy8qncp4sk4gkik73bq4n8slb97incz1jhrz7sl6fcgfz88b.nar.zst error="server returned 404: 404 page not found\n"15682026/11/10 21:12:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15692026/11/10 21:12:12 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15702026/11/10 21:12:12 INFO Signed narinfos id=1 count=315712026/11/10 21:12:12 INFO Uploading 3 narinfos15722026/11/10 21:12:12 INFO Received push request method=POST path=/api/pushes15732026/11/10 21:12:12 WARN Failed to register uploaded object key=qqlfscn7930dy105fkz7d8rq1m58bjxv.narinfo error="server returned 404: 404 page not found\n"15742026/11/10 21:12:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15752026/11/10 21:12:12 INFO Uploading ya1dljwx0jlq6151vlgfpf1ygpbnqs1g-pinned-file.txt (128B)15762026/11/10 21:12:12 WARN Failed to register uploaded object key=zp9f62avvbwwj4sw9393iy0qgbr68cy7.narinfo error="server returned 404: 404 page not found\n"15772026/11/10 21:12:12 INFO Received complete push request method=POST path=/api/pushes/1/complete15782026/11/10 21:12:12 WARN Failed to register uploaded object key=0vwdlk7dy9cir5359q732izcyg2db8ln.narinfo error="server returned 404: 404 page not found\n"15792026/11/10 21:12:12 INFO Completed push id=1 objects=8 duration=45.60125ms15802026/11/10 21:12:12 INFO Upload complete. (438ms)15812026/11/10 21:12:12 WARN Failed to register uploaded object key=ya1dljwx0jlq6151vlgfpf1ygpbnqs1g.ls error="server returned 404: 404 page not found\n"1582=== NAME TestClientPushesUseOnePush1583 client_pushes_test.go:97: Retrieved narinfo from S3:1584 StorePath: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientPushesUseOnePush2193912875/001/store/zp9f62avvbwwj4sw9393iy0qgbr68cy7-shared-dep1585 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1586 Compression: zstd1587 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821588 NarSize: 1361589 References: 1590 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1591 client_pushes_test.go:97: Retrieved narinfo from S3:1592 StorePath: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientPushesUseOnePush2193912875/001/store/qqlfscn7930dy105fkz7d8rq1m58bjxv-a1593 URL: nar/13ypvy8qncp4sk4gkik73bq4n8slb97incz1jhrz7sl6fcgfz88b.nar.zst1594 Compression: zstd1595 NarHash: sha256:13ypvy8qncp4sk4gkik73bq4n8slb97incz1jhrz7sl6fcgfz88b1596 NarSize: 2561597 References: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientPushesUseOnePush2193912875/001/store/zp9f62avvbwwj4sw9393iy0qgbr68cy7-shared-dep1598 CA: text:sha256:05n59d0ycy5k3fm8saigiqwxkmf2bhr3z7aw4939s0hrpxd09pik15992026/11/10 21:12:12 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16002026/11/10 21:12:12 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16012026/11/10 21:12:12 INFO Signed narinfos id=1 count=116022026/11/10 21:12:12 INFO Uploading 1 narinfos1603 client_pushes_test.go:97: Retrieved narinfo from S3:1604 StorePath: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientPushesUseOnePush2193912875/001/store/0vwdlk7dy9cir5359q732izcyg2db8ln-b1605 URL: nar/13ypvy8qncp4sk4gkik73bq4n8slb97incz1jhrz7sl6fcgfz88b.nar.zst1606 Compression: zstd1607 NarHash: sha256:13ypvy8qncp4sk4gkik73bq4n8slb97incz1jhrz7sl6fcgfz88b1608 NarSize: 2561609 References: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientPushesUseOnePush2193912875/001/store/zp9f62avvbwwj4sw9393iy0qgbr68cy7-shared-dep1610 CA: text:sha256:05n59d0ycy5k3fm8saigiqwxkmf2bhr3z7aw4939s0hrpxd09pik16112026/11/10 21:12:12 INFO Received complete push request method=POST path=/api/pushes/1/complete16122026/11/10 21:12:12 WARN Failed to register uploaded object key=ya1dljwx0jlq6151vlgfpf1ygpbnqs1g.narinfo error="server returned 404: 404 page not found\n"16132026/11/10 21:12:12 INFO Completed push id=1 objects=3 duration=36.030792ms16142026/11/10 21:12:12 INFO Upload complete. (361ms)1615--- PASS: TestClientPushesUseOnePush (9.99s)1616=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh16172026/11/10 21:12:12 INFO Received push request method=POST path=/api/pushes16182026/11/10 21:12:12 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16192026/11/10 21:12:12 INFO Uploading fzv9fkr3f37dyqzj71ng2wkjx48q2fx4-unpinned-file.txt (128B)16202026/11/10 21:12:12 WARN Failed to register uploaded object key=fzv9fkr3f37dyqzj71ng2wkjx48q2fx4.ls error="server returned 404: 404 page not found\n"16212026/11/10 21:12:12 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16222026/11/10 21:12:12 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16232026/11/10 21:12:12 INFO Signed narinfos id=2 count=116242026/11/10 21:12:12 INFO Uploading 1 narinfos16252026/11/10 21:12:13 INFO Received complete push request method=POST path=/api/pushes/2/complete16262026/11/10 21:12:13 WARN Failed to register uploaded object key=fzv9fkr3f37dyqzj71ng2wkjx48q2fx4.narinfo error="server returned 404: 404 page not found\n"16272026/11/10 21:12:13 INFO Completed push id=2 objects=3 duration=1.008459ms16282026/11/10 21:12:13 INFO Upload complete. (214ms)1629=== NAME TestClientWithDependencies1630 client_integration_test.go:660: Built derivation: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientWithDependencies3408188194/001/store/17a6xw6lkspizlp9n0bnak9xfx7gi29r-test-script16312026/11/10 21:12:13 INFO Starting cleanup of old closures method=DELETE path=/api/closures16322026/11/10 21:12:13 INFO Garbage collection started16332026/11/10 21:12:13 INFO Aborted multipart uploads count=0 kept=016342026/11/10 21:12:13 WARN Force mode enabled - objects will be deleted immediately without grace period1635 client_integration_test.go:662: Found 1 dependencies (including self)16362026/11/10 21:12:13 INFO Received push request method=POST path=/api/pushes16372026/11/10 21:12:13 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16382026/11/10 21:12:13 INFO Uploading 17a6xw6lkspizlp9n0bnak9xfx7gi29r-test-script (136B)16392026/11/10 21:12:13 WARN Failed to register uploaded object key=log/gwlsdc45n9f87vqrrkf32l7a1837c9hm-test-script.drv error="server returned 404: 404 page not found\n"16402026/11/10 21:12:13 INFO Received push request method=POST path=/api/pushes16412026/11/10 21:12:13 WARN Failed to register uploaded object key=17a6xw6lkspizlp9n0bnak9xfx7gi29r.ls error="server returned 404: 404 page not found\n"16422026/11/10 21:12:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16432026/11/10 21:12:13 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"16442026/11/10 21:12:13 INFO Signed narinfos id=1 count=116452026/11/10 21:12:13 INFO Uploading 1 narinfos16462026/11/10 21:12:13 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16472026/11/10 21:12:13 INFO Uploading 0n5m8js6qshhaf20vdhdnlppsx5qwq50-shared-dep (136B)16482026/11/10 21:12:13 INFO Uploading gj7fgj42hzj534d3y8zz0ydng4crvpcn-top (264B)16492026/11/10 21:12:13 INFO Received complete push request method=POST path=/api/pushes/1/complete16502026/11/10 21:12:13 WARN Failed to register uploaded object key=17a6xw6lkspizlp9n0bnak9xfx7gi29r.narinfo error="server returned 404: 404 page not found\n"16512026/11/10 21:12:13 WARN Failed to register uploaded object key=0n5m8js6qshhaf20vdhdnlppsx5qwq50.ls error="server returned 404: 404 page not found\n"16522026/11/10 21:12:13 INFO Completed push id=1 objects=4 duration=87.555458ms16532026/11/10 21:12:13 INFO Upload complete. (459ms)16542026/11/10 21:12:13 WARN Failed to register uploaded object key=nar/1n33gd8cnhk84p2x39mbry7fkdqwf2zslnrcsdw6cmprm1gbzbiy.nar.zst error="server returned 404: 404 page not found\n"1655 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/6/scratch/509dce1726107d78/build/TestClientWithDependencies3408188194/001/store) requires matching store prefix16562026/11/10 21:12:13 WARN Failed to register uploaded object key=gj7fgj42hzj534d3y8zz0ydng4crvpcn.ls error="server returned 404: 404 page not found\n"16572026/11/10 21:12:13 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16582026/11/10 21:12:13 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16592026/11/10 21:12:13 INFO Signed narinfos id=1 count=216602026/11/10 21:12:13 INFO Uploading 2 narinfos16612026/11/10 21:12:13 INFO lead: acquired remote=192.0.2.1:123416622026/11/10 21:12:13 WARN Failed to register uploaded object key=0n5m8js6qshhaf20vdhdnlppsx5qwq50.narinfo error="server returned 404: 404 page not found\n"16632026/11/10 21:12:13 INFO Received complete push request method=POST path=/api/pushes/1/complete16642026/11/10 21:12:13 WARN Failed to register uploaded object key=gj7fgj42hzj534d3y8zz0ydng4crvpcn.narinfo error="server returned 404: 404 page not found\n"16652026/11/10 21:12:13 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=016662026/11/10 21:12:13 INFO Completed push id=1 objects=6 duration=71.510834ms16672026/11/10 21:12:13 INFO Upload complete. (559ms)1668=== NAME TestClientSharedPathCommittedMidPush1669 client_integration_test.go:727: Retrieved narinfo from S3:1670 StorePath: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientSharedPathCommittedMidPush1232289942/001/store/0n5m8js6qshhaf20vdhdnlppsx5qwq50-shared-dep1671 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1672 Compression: zstd1673 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821674 NarSize: 1361675 References: 1676 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1677=== NAME TestClientMultipleUploads1678 client_integration_test.go:405: Created store path 0: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientMultipleUploads1281389234/001/store/kq5ikzl6bib00z9mw7x3vgjxmv1gkka9-test-file-0.txt1679=== NAME TestClientSharedPathCommittedMidPush1680 client_integration_test.go:727: Retrieved narinfo from S3:1681 StorePath: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientSharedPathCommittedMidPush1232289942/001/store/gj7fgj42hzj534d3y8zz0ydng4crvpcn-top1682 URL: nar/1n33gd8cnhk84p2x39mbry7fkdqwf2zslnrcsdw6cmprm1gbzbiy.nar.zst1683 Compression: zstd1684 NarHash: sha256:1n33gd8cnhk84p2x39mbry7fkdqwf2zslnrcsdw6cmprm1gbzbiy1685 NarSize: 2641686 References: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientSharedPathCommittedMidPush1232289942/001/store/0n5m8js6qshhaf20vdhdnlppsx5qwq50-shared-dep1687 CA: text:sha256:19cxss6d9xfbidxh9yg7jb081vs1q4d5vj102b8rnrsiyn4w8c9a16882026/11/10 21:12:13 INFO Vacuumed table table=pending_closures1689--- PASS: TestClientWithDependencies (9.90s)1690=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows16912026/11/10 21:12:13 INFO Vacuumed table table=pending_objects16922026/11/10 21:12:13 INFO Vacuumed table table=multipart_uploads16932026/11/10 21:12:13 INFO Vacuumed table table=closures1694--- PASS: TestClientSharedPathCommittedMidPush (10.14s)1695=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1696=== NAME TestClientMultipleUploads1697 client_integration_test.go:405: Created store path 1: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientMultipleUploads1281389234/001/store/fdr20q3m30danr39n233bpcfadjl2cf2-test-file-1.txt16982026/11/10 21:12:14 INFO Vacuumed table table=objects1699 client_integration_test.go:405: Created store path 2: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientMultipleUploads1281389234/001/store/9bzyjapn996w8krmjy62nmzxv01vp43m-test-file-2.txt17002026/11/10 21:12:14 INFO Received push request method=POST path=/api/pushes17012026/11/10 21:12:14 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17022026/11/10 21:12:14 INFO Uploading fdr20q3m30danr39n233bpcfadjl2cf2-test-file-1.txt (160B)17032026/11/10 21:12:14 INFO Uploading 9bzyjapn996w8krmjy62nmzxv01vp43m-test-file-2.txt (160B)17042026/11/10 21:12:14 INFO Uploading kq5ikzl6bib00z9mw7x3vgjxmv1gkka9-test-file-0.txt (160B)17052026/11/10 21:12:14 WARN Failed to register uploaded object key=fdr20q3m30danr39n233bpcfadjl2cf2.ls error="server returned 404: 404 page not found\n"1706=== NAME TestClientIntegration1707 client_integration_test.go:291: Created store path: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientIntegration3904104744/002/store/kjpkql13k2fhy11ql0ddqs4l8q79i3bq-test-file.txt17082026/11/10 21:12:14 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17092026/11/10 21:12:14 WARN Failed to register uploaded object key=kq5ikzl6bib00z9mw7x3vgjxmv1gkka9.ls error="server returned 404: 404 page not found\n"17102026/11/10 21:12:14 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17112026/11/10 21:12:14 WARN Failed to register uploaded object key=9bzyjapn996w8krmjy62nmzxv01vp43m.ls error="server returned 404: 404 page not found\n"17122026/11/10 21:12:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17132026/11/10 21:12:14 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17142026/11/10 21:12:14 INFO Signed narinfos id=1 count=317152026/11/10 21:12:14 INFO Uploading 3 narinfos17162026/11/10 21:12:14 WARN Failed to register uploaded object key=fdr20q3m30danr39n233bpcfadjl2cf2.narinfo error="server returned 404: 404 page not found\n"17172026/11/10 21:12:14 WARN Failed to register uploaded object key=kq5ikzl6bib00z9mw7x3vgjxmv1gkka9.narinfo error="server returned 404: 404 page not found\n"17182026/11/10 21:12:14 INFO Received complete push request method=POST path=/api/pushes/1/complete17192026/11/10 21:12:14 WARN Failed to register uploaded object key=9bzyjapn996w8krmjy62nmzxv01vp43m.narinfo error="server returned 404: 404 page not found\n"17202026/11/10 21:12:14 INFO Received push request method=POST path=/api/pushes17212026/11/10 21:12:14 INFO Completed push id=1 objects=9 duration=26.699209ms17222026/11/10 21:12:14 INFO Upload complete. (422ms)1723=== NAME TestClientMultipleUploads1724 client_integration_test.go:416: Uploaded 3 paths in 468.648375ms17252026/11/10 21:12:14 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17262026/11/10 21:12:14 INFO Uploading kjpkql13k2fhy11ql0ddqs4l8q79i3bq-test-file.txt (152B)17272026/11/10 21:12:14 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"17282026/11/10 21:12:14 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17292026/11/10 21:12:14 WARN Failed to register uploaded object key=kjpkql13k2fhy11ql0ddqs4l8q79i3bq.ls error="server returned 404: 404 page not found\n"17302026/11/10 21:12:14 INFO Signed narinfos id=1 count=117312026/11/10 21:12:14 INFO Uploading 1 narinfos1732--- PASS: TestClientMultipleUploads (10.11s)1733=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed17342026/11/10 21:12:14 INFO Received complete push request method=POST path=/api/pushes/1/complete17352026/11/10 21:12:14 WARN Failed to register uploaded object key=kjpkql13k2fhy11ql0ddqs4l8q79i3bq.narinfo error="server returned 404: 404 page not found\n"17362026/11/10 21:12:14 INFO Completed push id=1 objects=3 duration=44.927917ms17372026/11/10 21:12:14 INFO Upload complete. (307ms)17382026/11/10 21:12:14 INFO lead: released remote=192.0.2.1:123417392026/11/10 21:12:14 INFO All 1 paths already cached1740=== NAME TestClientIntegration1741 client_integration_test.go:317: Retrieved narinfo from S3:1742 StorePath: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientIntegration3904104744/002/store/kjpkql13k2fhy11ql0ddqs4l8q79i3bq-test-file.txt1743 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1744 Compression: zstd1745 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11746 NarSize: 1521747 References: 1748 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11749 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1750 client_integration_test.go:318: Decompressed .ls content (64 bytes):1751 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}17522026/11/10 21:12:14 INFO lead: acquired remote=192.0.2.1:123417532026/11/10 21:12:15 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=017542026/11/10 21:12:15 INFO Received create pin request method=POST path=/api/pins/myapp17552026/11/10 21:12:15 INFO Created/updated pin name=myapp store_path=/private/var/tb/6/scratch/509dce1726107d78/build/TestPinProtectsFromGC3535349557/001/store/ya1dljwx0jlq6151vlgfpf1ygpbnqs1g-pinned-file.txt narinfo_key=ya1dljwx0jlq6151vlgfpf1ygpbnqs1g.narinfo17562026/11/10 21:12:15 INFO Starting cleanup of old closures method=DELETE path=/api/closures17572026/11/10 21:12:15 INFO Garbage collection started17582026/11/10 21:12:15 INFO Aborted multipart uploads count=0 kept=017592026/11/10 21:12:15 WARN Force mode enabled - objects will be deleted immediately without grace period17602026/11/10 21:12:15 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=017612026/11/10 21:12:15 INFO Vacuumed table table=pending_closures17622026/11/10 21:12:15 INFO Vacuumed table table=pending_objects17632026/11/10 21:12:15 INFO Vacuumed table table=multipart_uploads17642026/11/10 21:12:15 INFO Vacuumed table table=closures17652026/11/10 21:12:15 INFO Vacuumed table table=objects17662026/11/10 21:12:15 INFO Received push request method=POST path=/api/pushes17672026/11/10 21:12:15 INFO Object in database but missing from S3 key=kjpkql13k2fhy11ql0ddqs4l8q79i3bq.ls17682026/11/10 21:12:15 WARN Found objects in DB but missing from S3, will re-upload count=117692026/11/10 21:12:15 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17702026/11/10 21:12:15 INFO Received complete push request method=POST path=/api/pushes/2/complete17712026/11/10 21:12:15 WARN Failed to register uploaded object key=kjpkql13k2fhy11ql0ddqs4l8q79i3bq.ls error="server returned 404: 404 page not found\n"17722026/11/10 21:12:15 INFO Completed push id=2 objects=3 duration=787.959µs17732026/11/10 21:12:15 INFO Upload complete. (121ms)1774 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1775 client_integration_test.go:335: Decompressed .ls content (49 bytes):1776 {"version":1,"root":{"type":"regular","size":39}}1777--- PASS: TestConnectWaitsForAPeerMigration (9.35s)1778=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1779=== NAME TestClientCADerivations1780 client_ca_test.go:136: Built CA derivation: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientCADerivations596331975/001/store/94biciysiapiv37k8npsgappzxbgvfpc-ca-test1781--- PASS: TestService_ReadScope_PublicByDefault (7.97s)1782=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1783=== NAME TestClientCADerivations1784 client_ca_test.go:139: Found 1 dependencies (including self)17852026/11/10 21:12:15 INFO Received push request method=POST path=/api/pushes17862026/11/10 21:12:15 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17872026/11/10 21:12:15 INFO Received complete push request method=POST path=/api/pushes/3/complete17882026/11/10 21:12:15 WARN Failed to register uploaded object key=kjpkql13k2fhy11ql0ddqs4l8q79i3bq.ls error="server returned 404: 404 page not found\n"17892026/11/10 21:12:15 INFO Completed push id=3 objects=3 duration=667.417µs17902026/11/10 21:12:15 INFO Upload complete. (121ms)1791=== NAME TestClientIntegration1792 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1793 client_integration_test.go:352: Decompressed .ls content (49 bytes):1794 {"version":1,"root":{"type":"regular","size":39}}1795 client_integration_test.go:363: Testing garbage collection...17962026/11/10 21:12:15 INFO Received push request method=POST path=/api/pushes17972026/11/10 21:12:15 INFO Starting cleanup of old closures method=DELETE path=/api/closures17982026/11/10 21:12:15 INFO Garbage collection started17992026/11/10 21:12:15 INFO Aborted multipart uploads count=0 kept=018002026/11/10 21:12:15 WARN Force mode enabled - objects will be deleted immediately without grace period18012026/11/10 21:12:15 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18022026/11/10 21:12:15 INFO Uploading 94biciysiapiv37k8npsgappzxbgvfpc-ca-test (144B)1803=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1804=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1805=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected18062026/11/10 21:12:16 INFO lead: released remote=192.0.2.1:12341807=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1808=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1809=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1810=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1811=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1812=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1813--- PASS: TestLeadElectsOneAndHandsOver (11.01s)1814=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18152026/11/10 21:12:16 WARN Failed to register uploaded object key=94biciysiapiv37k8npsgappzxbgvfpc.ls error="server returned 404: 404 page not found\n"18162026/11/10 21:12:16 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18172026/11/10 21:12:16 WARN Failed to register uploaded object key=log/4173wnbvs1k593bwhbflxhfvgjqjpqws-ca-test.drv error="server returned 404: 404 page not found\n"18182026/11/10 21:12:16 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18192026/11/10 21:12:16 INFO Signed narinfos id=1 count=118202026/11/10 21:12:16 INFO Uploading 1 narinfos18212026/11/10 21:12:16 INFO Received complete push request method=POST path=/api/pushes/1/complete18222026/11/10 21:12:16 WARN Failed to register uploaded object key=94biciysiapiv37k8npsgappzxbgvfpc.narinfo error="server returned 404: 404 page not found\n"18232026/11/10 21:12:16 INFO Completed push id=1 objects=4 duration=30.249125ms18242026/11/10 21:12:16 INFO Upload complete. (406ms)1825--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (9.79s)1826=== CONT TestParseSingleRange/none1827=== NAME TestClientCADerivations1828 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientCADerivations596331975/001/store/94biciysiapiv37k8npsgappzxbgvfpc-ca-test1829 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1830 Compression: zstd1831 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1832 NarSize: 1441833 References: 1834 Deriver: /private/var/tb/6/scratch/509dce1726107d78/build/TestClientCADerivations596331975/001/store/4173wnbvs1k593bwhbflxhfvgjqjpqws-ca-test.drv1835 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1836 client_ca_test.go:185: Checking for realisation files in S3...1837=== CONT TestIsValidCachePath/narinfo1838=== CONT TestIsValidCachePath/leading_slash1839=== CONT TestParseSingleRange/start_far_past_EOF1840=== CONT TestParseSingleRange/start_past_EOF1841=== CONT TestParseSingleRange/single_byte1842=== CONT TestParseSingleRange/suffix_exceeds_size1843=== CONT TestParseSingleRange/suffix1844=== CONT TestParseSingleRange/end_clamped_to_size1845=== CONT TestParseSingleRange/open-ended1846=== CONT TestParseSingleRange/closed1847=== CONT TestParseSingleRange/malformed_end_before_start1848=== CONT TestParseSingleRange/malformed_both_empty1849=== CONT TestParseSingleRange/malformed_no_dash1850=== CONT TestParseSingleRange/multi-range_ignored1851=== CONT TestParseSingleRange/unknown_unit1852--- PASS: TestParseSingleRange (0.00s)1853 --- PASS: TestParseSingleRange/none (0.00s)1854 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1855 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1856 --- PASS: TestParseSingleRange/single_byte (0.00s)1857 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1858 --- PASS: TestParseSingleRange/suffix (0.00s)1859 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1860 --- PASS: TestParseSingleRange/open-ended (0.00s)1861 --- PASS: TestParseSingleRange/closed (0.00s)1862 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1863 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1864 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1865 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1866 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1867=== CONT TestIsValidCachePath/nix-cache-info1868=== CONT TestIsValidCachePath/empty1869=== CONT TestIsValidCachePath/random_path1870=== CONT TestIsValidCachePath/invalid_char_u1871=== CONT TestIsValidCachePath/invalid_char_e1872=== CONT TestIsValidCachePath/traversal_in_middle1873=== CONT TestIsValidCachePath/traversal_parent1874=== CONT TestIsValidCachePath/index.html1875=== CONT TestIsValidCachePath/short_hash1876=== CONT TestIsValidCachePath/nar_uncompressed1877=== CONT TestIsValidCachePath/realisation1878=== CONT TestIsValidCachePath/log1879=== CONT TestIsValidCachePath/ls1880=== CONT TestIsValidCachePath/nar_xz1881=== CONT TestIsValidCachePath/nar_bz21882=== CONT TestIsValidCachePath/nar_zst1883=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1884=== CONT TestIsValidCachePath/wrong_extension1885--- PASS: TestIsValidCachePath (0.01s)1886 --- PASS: TestIsValidCachePath/narinfo (0.00s)1887 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1888 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1889 --- PASS: TestIsValidCachePath/empty (0.00s)1890 --- PASS: TestIsValidCachePath/random_path (0.00s)1891 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1892 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1893 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1894 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1895 --- PASS: TestIsValidCachePath/index.html (0.00s)1896 --- PASS: TestIsValidCachePath/short_hash (0.00s)1897 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1898 --- PASS: TestIsValidCachePath/realisation (0.00s)1899 --- PASS: TestIsValidCachePath/log (0.00s)1900 --- PASS: TestIsValidCachePath/ls (0.00s)1901 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1902 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1903 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1904 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1905 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1906=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19072026/11/10 21:12:16 INFO Received uploads request method=POST path=/1908=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19092026/11/10 21:12:16 INFO Received complete multipart upload request method=POST path=/1910=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19112026/11/10 21:12:16 INFO Received request for more parts method=POST path=/1912=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19132026/11/10 21:12:16 INFO Received uploads request method=POST path=/1914--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)1915 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1916 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1917 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1918 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1919=== CONT TestIsValidUploadKey/narinfo1920=== CONT TestIsValidUploadKey/realisation_plus_in_output1921=== CONT TestIsValidUploadKey/unknown_type1922=== CONT TestIsValidUploadKey/empty_key1923=== CONT TestIsValidUploadKey/absolute1924=== CONT TestIsValidUploadKey/traversal_nar1925=== CONT TestIsValidUploadKey/traversal1926=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1927=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1928=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1929=== CONT TestIsValidUploadKey/index.html1930=== CONT TestIsValidUploadKey/nix-cache-info1931=== CONT TestIsValidUploadKey/build_log_home-manager_file1932=== CONT TestIsValidUploadKey/realisation1933=== CONT TestIsValidUploadKey/build_log_equals1934=== CONT TestIsValidUploadKey/build_log_question_mark1935=== CONT TestIsValidUploadKey/build_log_plus_in_name1936=== CONT TestIsValidUploadKey/nar_plain1937=== CONT TestIsValidUploadKey/build_log1938=== CONT TestIsValidUploadKey/listing1939=== CONT TestIsValidUploadKey/nar_xz1940=== CONT TestIsValidUploadKey/nar_zst1941=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart1942--- PASS: TestIsValidUploadKey (0.00s)1943 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1944 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1945 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1946 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1947 --- PASS: TestIsValidUploadKey/absolute (0.00s)1948 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1949 --- PASS: TestIsValidUploadKey/traversal (0.00s)1950 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1951 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1952 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1953 --- PASS: TestIsValidUploadKey/index.html (0.00s)1954 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1955 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1956 --- PASS: TestIsValidUploadKey/realisation (0.00s)1957 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1958 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1959 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1960 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1961 --- PASS: TestIsValidUploadKey/build_log (0.00s)1962 --- PASS: TestIsValidUploadKey/listing (0.00s)1963 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1964 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)19652026/11/10 21:12:16 INFO Received complete multipart upload request method=POST path=/1966=== NAME TestClientCADerivations1967 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1968 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1969=== CONT TestPendingClosureWriteTimeout/empty1970=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19712026/11/10 21:12:16 INFO Received uploads request method=POST path=/19722026/11/10 21:12:16 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19732026/11/10 21:12:16 WARN mTLS auth: bound subjects configured but subject DN unavailable19742026/11/10 21:12:16 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1975--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (7.83s)1976=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19772026/11/10 21:12:16 INFO Received request for more parts method=POST path=/1978=== NAME TestClientCADerivations1979 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket79?endpoint=http://localhost:52859®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/6/scratch/509dce1726107d78/build/TestClientCADerivations596331975/001/store'1980 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11981=== CONT TestPendingClosureWriteTimeout/670k_objects1982=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline19832026/11/10 21:12:16 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=01984--- PASS: TestUploadHandlersRejectOversizedBody (0.07s)1985 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1986 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1987 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.27s)1988=== CONT TestPendingClosureWriteTimeout/400_objects1989=== CONT TestProxyWriteTimeout/narinfo1990=== CONT TestProxyWriteTimeout/10_GiB_nar1991=== CONT TestProxyWriteTimeout/unknown_size1992=== CONT TestProxyWriteTimeout/1_GiB_nar1993--- PASS: TestProxyWriteTimeout (0.00s)1994 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1995 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1996 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1997 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1998=== CONT TestPush_RejectsBadRequests/no_objects19992026/11/10 21:12:16 INFO Received push request method=POST path=/api/pushes2000=== CONT TestPush_RejectsBadRequests/root_not_in_objects20012026/11/10 21:12:16 INFO Received push request method=POST path=/api/pushes2002=== CONT TestPush_RejectsBadRequests/no_roots20032026/11/10 21:12:16 INFO Received push request method=POST path=/api/pushes2004=== CONT TestPush_RejectsBadRequests/bad_root20052026/11/10 21:12:16 INFO Received push request method=POST path=/api/pushes2006=== CONT TestServerTLSConfig/no_client_CA2007=== CONT TestServerTLSConfig/not_a_PEM_file2008--- PASS: TestPush_RejectsBadRequests (6.90s)2009 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2010 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2011 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2012 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2013=== CONT TestServerTLSConfig/missing_CA_file2014--- PASS: TestServerTLSConfig (0.00s)2015 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2016 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)2017 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2018=== CONT TestResolveDBConnectionString/flag_wins2019=== CONT TestResolveDBConnectionString/PGHOST_allows_empty20202026/11/10 21:12:16 INFO Vacuumed table table=pending_closures2021=== CONT TestResolveDBConnectionString/nothing_configured2022=== CONT TestResolveDBConnectionString/missing_file_is_an_error2023=== CONT TestResolveDBConnectionString/file_when_flag_empty2024=== CONT TestClientErrorHandling/ServerNotAvailable2025--- PASS: TestResolveDBConnectionString (0.04s)2026 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2027 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2028 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2029 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2030 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)20312026/11/10 21:12:16 INFO Vacuumed table table=pending_objects20322026/11/10 21:12:16 INFO Vacuumed table table=multipart_uploads2033--- PASS: TestClientCADerivations (10.01s)2034=== CONT TestClientErrorHandling/InvalidStorePath20352026/11/10 21:12:16 INFO Vacuumed table table=closures20362026/11/10 21:12:16 INFO Vacuumed table table=objects2037--- PASS: TestService_ReadAuthMiddleware (8.05s)2038=== CONT TestClientErrorHandling/InvalidAuthToken20392026/11/10 21:12:16 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/present20402026/11/10 21:12:16 WARN Request failed, retrying attempt=2 backoff=184.892835ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20412026/11/10 21:12:17 WARN Request failed, retrying attempt=3 backoff=435.478566ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20422026/11/10 21:12:17 INFO Aborted multipart uploads count=0 kept=020432026/11/10 21:12:17 WARN Force mode enabled - objects will be deleted immediately without grace period2044=== NAME TestPinProtectsFromGC2045 client_integration_test.go:887: Pin successfully protected closure from garbage collection20462026/11/10 21:12: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=020472026/11/10 21:12:17 INFO Vacuumed table table=pending_closures20482026/11/10 21:12:17 INFO Vacuumed table table=pending_objects20492026/11/10 21:12:17 INFO Vacuumed table table=multipart_uploads20502026/11/10 21:12:17 INFO Vacuumed table table=closures2051--- PASS: TestPinProtectsFromGC (13.97s)2052=== CONT TestCacheConfigHandler/full_config,_no_issuer2053=== CONT TestCacheConfigHandler/upstream_keys_advertised2054=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2055=== CONT TestCacheConfigHandler/no_cache_url_configured2056=== CONT TestCacheConfigHandler/no_signing_keys2057--- PASS: TestCacheConfigHandler (0.00s)2058 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2059 --- PASS: TestCacheConfigHandler/upstream_keys_advertised (0.00s)2060 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2061 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2062 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2063=== CONT TestGCEndsOnShutdown/before_the_run20642026/11/10 21:12:17 INFO Vacuumed table table=objects2065--- PASS: TestSweepRechecksPendingAfterLocking (8.60s)2066=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete2067=== RUN TestService_RequireScope_OIDC/builder_may_write2068=== PAUSE TestService_RequireScope_OIDC/builder_may_write2069=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2070=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2071=== RUN TestService_RequireScope_OIDC/ops_may_admin2072=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2073=== RUN TestService_RequireScope_OIDC/ops_may_not_write2074=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2075=== RUN TestService_RequireScope_OIDC/reader_may_not_write2076=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2077=== RUN TestService_RequireScope_OIDC/static_token_may_admin2078=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2079=== RUN TestService_RequireScope_OIDC/static_token_may_write2080=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2081=== RUN TestService_RequireScope_OIDC/reader_may_read2082=== PAUSE TestService_RequireScope_OIDC/reader_may_read2083=== RUN TestService_RequireScope_OIDC/writer_implies_read2084=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2085=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2086=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2087=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc2088=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc2089=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2090=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2091=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2092=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2093=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2094=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2095=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark20962026/11/10 21:12:17 WARN Request failed, retrying attempt=4 backoff=764.079343ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2097--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (9.17s)2098=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2099=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21002026/11/10 21:12:17 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]2101=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2102=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected21032026/11/10 21:12:17 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021042026/11/10 21:12:17 WARN Authentication failed token_preview=eyJhbGciOi...2P0OZg8Uzw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2105=== NAME TestClientIntegration2106 client_integration_test.go:370: Objects in database after GC:2107=== CONT TestService_RequireScope_OIDC/builder_may_write2108=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2109=== NAME TestClientIntegration2110 client_integration_test.go:370: Successfully deleted all objects with GC --force2111=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2112=== CONT TestService_RequireScope_OIDC/writer_implies_read2113=== CONT TestService_RequireScope_OIDC/reader_may_read2114=== CONT TestService_RequireScope_OIDC/static_token_may_write2115=== CONT TestService_RequireScope_OIDC/static_token_may_admin2116=== CONT TestService_RequireScope_OIDC/reader_may_not_write2117--- PASS: TestService_AuthMiddleware_OIDC (8.07s)2118 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2119 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2120 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2121 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.02s)2122=== CONT TestService_RequireScope_OIDC/ops_may_not_write2123=== CONT TestService_RequireScope_OIDC/ops_may_admin2124=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2125=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2126=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read21272026/11/10 21:12:17 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]2128=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2129--- PASS: TestService_RequireScope_OIDC (8.98s)2130 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2131 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2132 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2133 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2134 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2135 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2136 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2137 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2138 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2139 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2140 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2141 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2142 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2143 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2144--- PASS: TestClientIntegration (12.80s)21452026/11/10 21:12:18 WARN Request failed, retrying attempt=5 backoff=1.757708998s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21462026/11/10 21:12:18 INFO Aborted multipart uploads count=0 kept=021472026/11/10 21:12:18 WARN Force mode enabled - objects will be deleted immediately without grace period21482026/11/10 21:12: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=021492026/11/10 21:12:18 INFO Vacuumed table table=pending_closures21502026/11/10 21:12:19 INFO Received uploads request method=POST path=/api/pending_closures21512026/11/10 21:12:19 INFO Vacuumed table table=pending_objects21522026/11/10 21:12:19 INFO Vacuumed table table=multipart_uploads21532026/11/10 21:12:19 INFO Vacuumed table table=closures21542026/11/10 21:12:19 INFO Vacuumed table table=objects2155--- PASS: TestCommitRacingPendingCleanupKeepsObjects (9.68s)21562026/11/10 21:12:19 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"2157--- PASS: TestService_AuthMiddleware (8.87s)2158--- PASS: TestPushWaitsForSweepHoldingRow (9.50s)2159--- PASS: TestGetExistingObjectsLocksRows (8.77s)21602026/11/10 21:12:20 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21612026/11/10 21:12:20 WARN Request failed, retrying attempt=2 backoff=183.354326ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21622026/11/10 21:12:20 WARN Request failed, retrying attempt=3 backoff=365.893162ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21632026/11/10 21:12:20 WARN Request failed, retrying attempt=4 backoff=802.576103ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21642026/11/10 21:12:20 INFO Received uploads request method=POST path=/api/pending_closures21652026/11/10 21:12:20 INFO Aborted multipart uploads count=0 kept=021662026/11/10 21:12:20 WARN Force mode enabled - objects will be deleted immediately without grace period2167--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2168 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (9.49s)2169 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (8.17s)21702026/11/10 21:12:21 INFO Received uploads request method=POST path=/api/pending_closures21712026/11/10 21:12:21 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=021722026/11/10 21:12:21 INFO Vacuumed table table=pending_closures21732026/11/10 21:12:21 INFO Vacuumed table table=pending_objects21742026/11/10 21:12:21 INFO Vacuumed table table=multipart_uploads21752026/11/10 21:12:21 INFO Vacuumed table table=closures21762026/11/10 21:12:21 INFO Vacuumed table table=objects2177--- PASS: TestDeleteClosuresRacingPins (14.32s)21782026/11/10 21:12:21 INFO Received uploads request method=POST path=/api/pending_closures21792026/11/10 21:12:21 WARN Request failed, retrying attempt=5 backoff=1.596523227s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21802026/11/10 21:12:21 INFO Received uploads request method=POST path=/api/pending_closures21812026/11/10 21:12:22 INFO Received uploads request method=POST path=/api/pending_closures21822026/11/10 21:12:22 INFO Received uploads request method=POST path=/api/pending_closures21832026/11/10 21:12:23 INFO Received uploads request method=POST path=/api/pending_closures21842026/11/10 21:12:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21852026/11/10 21:12:23 INFO Aborted multipart uploads count=0 kept=021862026/11/10 21:12:23 WARN Force mode enabled - objects will be deleted immediately without grace period21872026/11/10 21:12: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=021882026/11/10 21:12:23 INFO Vacuumed table table=pending_closures21892026/11/10 21:12:23 INFO Vacuumed table table=pending_objects21902026/11/10 21:12:23 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLmI1MjZlNzYyLTQzZTctNDc0Ni04Y2U0LTFiOTgzNDQyMjExOXgxNzk0MzQ1MTQxMjEyNjc2MDAw parts=1021912026/11/10 21:12:23 INFO Vacuumed table table=multipart_uploads21922026/11/10 21:12:23 INFO Vacuumed table table=closures21932026/11/10 21:12:23 INFO Vacuumed table table=objects21942026/11/10 21:12:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21952026/11/10 21:12:23 INFO Completed upload id=1 objects=3 duration=15.448166ms2196--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2197 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (7.54s)2198 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (7.34s)21992026/11/10 21:12:23 INFO Received uploads request method=POST path=/api/pending_closures22002026/11/10 21:12:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22012026/11/10 21:12:23 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLjg4OWVmMjhkLWExMTItNDI3OC1iMWRkLWMxMjJmMmRjZjY1YXgxNzk0MzQ1MTQxNTc1MzY1MDAw parts=1022022026/11/10 21:12:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22032026/11/10 21:12:23 INFO Completed upload id=1 objects=3 duration=22.600625ms22042026/11/10 21:12:23 INFO Received uploads request method=POST path=/api/pending_closures22052026/11/10 21:12:23 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst22062026/11/10 21:12:23 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo22072026/11/10 21:12:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22082026/11/10 21:12:24 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLmE5YmQ5MjZiLTM1ZmMtNGQ3Ni1iMjliLTc4NmRmNjFlODM1M3gxNzk0MzQ1MTQxOTEyNTA5MDAw parts=1022092026/11/10 21:12:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22102026/11/10 21:12:24 INFO Completed upload id=1 objects=3 duration=10.536833ms22112026/11/10 21:12:24 INFO Received uploads request method=POST path=/api/pending_closures22122026/11/10 21:12:24 INFO Received uploads request method=POST path=/api/pending_closures22132026/11/10 21:12:24 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22142026/11/10 21:12:24 WARN Found objects in DB but missing from S3, will re-upload count=122152026/11/10 21:12:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2216--- PASS: TestPendingClosureWriteTimeout (0.00s)2217 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2218 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2219 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2220 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (7.83s)22212026/11/10 21:12:24 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLjI2MDBmNjYzLTZiNDAtNDNiYi1hMGNlLTZlMWM4M2EyNmM4OXgxNzk0MzQ1MTQyMjY1Njg2MDAw parts=1022222026/11/10 21:12:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22232026/11/10 21:12:24 INFO Completed upload id=1 objects=3 duration=6.665708ms22242026/11/10 21:12:24 INFO Received uploads request method=POST path=/api/pending_closures22252026/11/10 21:12:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22262026/11/10 21:12:24 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22272026/11/10 21:12:24 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLmY2OWMzZWE2LTFjODktNGRiZC1hNGIyLTU2ODA5YzQ1YjYzYXgxNzk0MzQ1MTQyNjM1OTg4MDAw parts=1022282026/11/10 21:12:24 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22292026/11/10 21:12:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22302026/11/10 21:12:24 INFO Completed upload id=1 objects=3 duration=5.684417ms22312026/11/10 21:12:24 INFO Received uploads request method=POST path=/api/pending_closures2232--- PASS: TestClientErrorHandling (0.01s)2233 --- PASS: TestClientErrorHandling/ServerNotAvailable (6.93s)2234 --- PASS: TestClientErrorHandling/InvalidStorePath (7.30s)2235 --- PASS: TestClientErrorHandling/InvalidAuthToken (8.13s)22362026/11/10 21:12:25 INFO Aborted multipart uploads count=0 kept=022372026/11/10 21:12:25 WARN Force mode enabled - objects will be deleted immediately without grace period22382026/11/10 21:12:25 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:52859/bucket105/?delete=\": context canceled"22392026/11/10 21:12:25 INFO Aborted multipart uploads count=0 kept=022402026/11/10 21:12:25 WARN Force mode enabled - objects will be deleted immediately without grace period22412026-11-10 21:12:25.344 UTC [91419] ERROR: canceling statement due to user request22422026-11-10 21:12:25.344 UTC [91419] STATEMENT: -- name: MarkStaleObjects :execrows2243 WITH RECURSIVE ct AS (2244 SELECT timezone('UTC', now()) AS now2245 ),2246 closure_reach AS (2247 -- Start with all closure keys2248 SELECT o.key, o.refs2249 FROM objects o2250 INNER JOIN closures c ON o.key = c.key2251 UNION2252 -- Recursively add all referenced objects2253 SELECT o.key, o.refs2254 FROM objects o2255 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2256 ),2257 reachable_objects AS (2258 SELECT DISTINCT key FROM closure_reach2259 ),2260 stale_objects AS (2261 SELECT o.key2262 FROM objects AS o, ct2263 WHERE2264 NOT EXISTS (2265 SELECT 12266 FROM reachable_objects ro2267 WHERE ro.key = o.key2268 )2269 AND NOT EXISTS (2270 SELECT 12271 FROM pending_objects AS po2272 WHERE po.key = o.key2273 )2274 AND o.deleted_at IS NULL -- Only mark fresh objects2275 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2276 FOR UPDATE2277 )2278 UPDATE objects2279 SET2280 deleted_at = ct.now,2281 first_deleted_at = COALESCE(first_deleted_at, ct.now)2282 FROM stale_objects, ct2283 WHERE objects.key = stale_objects.key2284 2285--- PASS: TestGCEndsOnShutdown (0.00s)2286 --- PASS: TestGCEndsOnShutdown/before_the_run (7.34s)2287 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (7.66s)2288 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (7.85s)22892026/11/10 21:12:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22902026/11/10 21:12:26 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLjAwMzZiZmQ5LTY1YWQtNDhiMC04MjcyLWI1MTViOGU1ODI3OHgxNzk0MzQ1MTQ0MDk5ODU2MDAw parts=1022912026/11/10 21:12:26 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22922026/11/10 21:12:26 INFO Completed upload id=2 objects=3 duration=967µs22932026/11/10 21:12:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22942026/11/10 21:12:27 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=ZmQ0ODg3Y2UtNTRlMi00ZDQ2LTljMmMtNjNmMjM5Y2U4NDAwLmRkZDZiMmRlLTVkMjUtNDczZS05MTVmLWMwNGNmNjY1Yjk4NHgxNzk0MzQ1MTQ0NDIyNzgyMDAw parts=1022952026/11/10 21:12:27 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22962026/11/10 21:12:27 INFO Completed upload id=2 objects=3 duration=1.866ms22972026/11/10 21:12:27 INFO Received uploads request method=POST path=/api/pending_closures22982026/11/10 21:12:27 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22992026/11/10 21:12:27 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo23002026/11/10 21:12:28 INFO Received uploads request method=POST path=/api/pending_closures23012026/11/10 21:12:28 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst23022026/11/10 21:12:28 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2303--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.00s)2304 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (9.85s)2305 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (9.44s)2306 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (8.86s)2307 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (12.03s)2308 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (12.57s)2309=== NAME TestOrphanedObjectsGCStressTest2310 orphaned_objects_gc_test.go:503: Stress test completed successfully:2311 orphaned_objects_gc_test.go:504: - Active objects preserved: 202312 orphaned_objects_gc_test.go:505: - Objects deleted: 2102313 orphaned_objects_gc_test.go:506: - Total GC'd: 2102314--- PASS: TestOrphanedObjectsGCStressTest (44.16s)2315PASS2316{"timestamp":"2026-11-10T21:12:31.263921Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53237","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}2317{"timestamp":"2026-11-10T21:12:31.264014Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53349","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}2318{"timestamp":"2026-11-10T21:12:31.264388Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53361","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}23192026-11-10 21:12:31.372 UTC [90935] LOG: received smart shutdown request23202026-11-10 21:12:31.373 UTC [90935] LOG: background worker "logical replication launcher" (PID 90946) exited with exit code 123212026-11-10 21:12:31.419 UTC [90940] LOG: shutting down23222026-11-10 21:12:31.419 UTC [90940] LOG: checkpoint starting: shutdown immediate23232026-11-10 21:12:32.744 UTC [90940] LOG: checkpoint complete: wrote 12105 buffers (73.9%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.577 s, sync=0.734 s, total=1.326 s; sync files=36061, longest=0.036 s, average=0.001 s; distance=529850 kB, estimate=529850 kB; lsn=0/21CFB790, redo lsn=0/21CFB79023242026-11-10 21:12:32.751 UTC [90935] LOG: database system is shut down2325Running OIDC tests...2326=== RUN TestAudienceForIssuer2327=== PAUSE TestAudienceForIssuer2328=== RUN TestGlobMatch2329=== PAUSE TestGlobMatch2330=== RUN TestValidateToken_ValidToken2331=== PAUSE TestValidateToken_ValidToken2332=== RUN TestValidateToken_WrongAudience2333=== PAUSE TestValidateToken_WrongAudience2334=== RUN TestValidateToken_Expired2335=== PAUSE TestValidateToken_Expired2336=== RUN TestValidateToken_BoundClaimsMismatch2337=== PAUSE TestValidateToken_BoundClaimsMismatch2338=== RUN TestValidateToken_BoundSubjectMismatch2339=== PAUSE TestValidateToken_BoundSubjectMismatch2340=== RUN TestValidateToken_MultipleProviders2341=== PAUSE TestValidateToken_MultipleProviders2342=== RUN TestValidateToken_NoMatchingProvider2343=== PAUSE TestValidateToken_NoMatchingProvider2344=== RUN TestValidateToken_KubernetesServiceAccount2345=== PAUSE TestValidateToken_KubernetesServiceAccount2346=== RUN TestNewValidator_KubernetesRequiresCA2347=== PAUSE TestNewValidator_KubernetesRequiresCA2348=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2349=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2350=== RUN TestPins_ReservedForMatchingRule2351=== PAUSE TestPins_ReservedForMatchingRule2352=== RUN TestPins_TopLevelShorthand2353=== PAUSE TestPins_TopLevelShorthand2354=== RUN TestPins_ConfigValidation2355=== PAUSE TestPins_ConfigValidation2356=== RUN TestScopes_LegacyProviderDefaultsToWrite2357=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2358=== RUN TestScopes_Rules2359=== PAUSE TestScopes_Rules2360=== RUN TestScopes_ConfigValidation2361=== PAUSE TestScopes_ConfigValidation2362=== CONT TestAudienceForIssuer2363--- PASS: TestAudienceForIssuer (0.00s)2364=== CONT TestValidateToken_NoMatchingProvider2365=== CONT TestValidateToken_Expired2366=== CONT TestValidateToken_KubernetesServiceAccount2367=== CONT TestPins_ReservedForMatchingRule2368=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2369=== CONT TestNewValidator_KubernetesRequiresCA2370=== CONT TestValidateToken_ValidToken2371=== CONT TestValidateToken_BoundSubjectMismatch2372=== CONT TestValidateToken_BoundClaimsMismatch2373=== CONT TestGlobMatch2374=== RUN TestGlobMatch/foo_foo2375=== PAUSE TestGlobMatch/foo_foo2376=== RUN TestGlobMatch/foo_bar2377=== PAUSE TestGlobMatch/foo_bar2378=== RUN TestGlobMatch/*_2379=== PAUSE TestGlobMatch/*_2380=== RUN TestGlobMatch/*_anything2381=== PAUSE TestGlobMatch/*_anything2382=== RUN TestGlobMatch/foo*_foo2383=== PAUSE TestGlobMatch/foo*_foo2384=== RUN TestGlobMatch/foo*_foobar2385=== PAUSE TestGlobMatch/foo*_foobar2386=== RUN TestGlobMatch/foo*_bar2387=== PAUSE TestGlobMatch/foo*_bar2388=== RUN TestGlobMatch/*bar_bar2389=== PAUSE TestGlobMatch/*bar_bar2390=== RUN TestGlobMatch/*bar_foobar2391=== PAUSE TestGlobMatch/*bar_foobar2392=== RUN TestGlobMatch/*bar_foo2393=== PAUSE TestGlobMatch/*bar_foo2394=== RUN TestGlobMatch/foo*bar_foobar2395=== PAUSE TestGlobMatch/foo*bar_foobar2396=== RUN TestGlobMatch/foo*bar_foo123bar2397=== PAUSE TestGlobMatch/foo*bar_foo123bar2398=== RUN TestGlobMatch/foo*bar_foobarbaz2399=== PAUSE TestGlobMatch/foo*bar_foobarbaz2400=== RUN TestGlobMatch/*/*_foo/bar2401=== PAUSE TestGlobMatch/*/*_foo/bar2402=== RUN TestGlobMatch/*/*_foo2403=== PAUSE TestGlobMatch/*/*_foo2404=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2405=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2406=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02407=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02408=== RUN TestGlobMatch/refs/*/main_refs/heads/main2409=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2410=== RUN TestGlobMatch/fo?_foo2411=== PAUSE TestGlobMatch/fo?_foo2412=== RUN TestGlobMatch/fo?_fo2413=== PAUSE TestGlobMatch/fo?_fo2414=== RUN TestGlobMatch/fo?_fooo2415=== PAUSE TestGlobMatch/fo?_fooo2416=== RUN TestGlobMatch/?oo_foo2417=== PAUSE TestGlobMatch/?oo_foo2418=== RUN TestGlobMatch/?oo_boo2419=== PAUSE TestGlobMatch/?oo_boo2420=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2421=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2422=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2423=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2424=== CONT TestGlobMatch/foo_foo2425=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2426=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2427=== CONT TestGlobMatch/?oo_boo2428=== CONT TestGlobMatch/?oo_foo2429=== CONT TestGlobMatch/fo?_fooo2430=== CONT TestGlobMatch/fo?_fo2431=== CONT TestGlobMatch/fo?_foo2432=== CONT TestGlobMatch/refs/*/main_refs/heads/main2433=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02434=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2435=== CONT TestGlobMatch/*/*_foo2436=== CONT TestGlobMatch/*/*_foo/bar2437=== CONT TestGlobMatch/foo*bar_foobarbaz2438=== CONT TestGlobMatch/foo*bar_foo123bar2439=== CONT TestGlobMatch/foo*bar_foobar2440=== CONT TestGlobMatch/*bar_foo2441=== CONT TestGlobMatch/*bar_foobar2442=== CONT TestGlobMatch/*bar_bar2443=== CONT TestGlobMatch/foo*_bar2444=== CONT TestGlobMatch/foo*_foobar2445=== CONT TestGlobMatch/foo*_foo2446=== CONT TestGlobMatch/*_anything2447=== CONT TestGlobMatch/*_2448=== CONT TestGlobMatch/foo_bar2449--- PASS: TestGlobMatch (0.00s)2450 --- PASS: TestGlobMatch/foo_foo (0.00s)2451 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2452 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2453 --- PASS: TestGlobMatch/?oo_boo (0.00s)2454 --- PASS: TestGlobMatch/?oo_foo (0.00s)2455 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2456 --- PASS: TestGlobMatch/fo?_fo (0.00s)2457 --- PASS: TestGlobMatch/fo?_foo (0.00s)2458 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2459 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2460 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2461 --- PASS: TestGlobMatch/*/*_foo (0.00s)2462 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2463 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2464 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2465 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2466 --- PASS: TestGlobMatch/*bar_foo (0.00s)2467 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2468 --- PASS: TestGlobMatch/*bar_bar (0.00s)2469 --- PASS: TestGlobMatch/foo*_bar (0.00s)2470 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2471 --- PASS: TestGlobMatch/foo*_foo (0.00s)2472 --- PASS: TestGlobMatch/*_anything (0.00s)2473 --- PASS: TestGlobMatch/*_ (0.00s)2474 --- PASS: TestGlobMatch/foo_bar (0.00s)2475=== CONT TestValidateToken_MultipleProviders2476=== CONT TestValidateToken_WrongAudience2477=== CONT TestPins_ConfigValidation2478--- PASS: TestPins_ConfigValidation (0.00s)2479=== CONT TestScopes_ConfigValidation2480=== CONT TestScopes_Rules2481--- PASS: TestScopes_ConfigValidation (0.00s)2482=== CONT TestScopes_LegacyProviderDefaultsToWrite2483=== CONT TestPins_TopLevelShorthand24842026/11/10 21:12:34 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5337324852026/11/10 21:12:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53375/oidc2486--- PASS: TestValidateToken_KubernetesServiceAccount (0.05s)24872026/11/10 21:12:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53377/oidc24882026/11/10 21:12:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53381/oidc2489--- PASS: TestPins_ReservedForMatchingRule (0.06s)2490--- PASS: TestValidateToken_Expired (0.06s)2491--- PASS: TestValidateToken_ValidToken (0.06s)24922026/11/10 21:12:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53385/oidc2493--- PASS: TestValidateToken_BoundSubjectMismatch (0.07s)24942026/11/10 21:12:34 http: TLS handshake error from 127.0.0.1:53384: read tcp 127.0.0.1:53383->127.0.0.1:53384: use of closed network connection2495--- PASS: TestNewValidator_KubernetesRequiresCA (0.07s)24962026/11/10 21:12:34 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232497--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.07s)24982026/11/10 21:12:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53389/oidc2499--- PASS: TestScopes_Rules (0.06s)25002026/11/10 21:12:34 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:53378/oidc25012026/11/10 21:12:34 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:53392/oidc25022026/11/10 21:12:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53395/oidc2503--- PASS: TestValidateToken_MultipleProviders (0.11s)2504--- PASS: TestValidateToken_BoundClaimsMismatch (0.11s)25052026/11/10 21:12:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53397/oidc2506--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.10s)25072026/11/10 21:12:34 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:53391/oidc2508--- PASS: TestValidateToken_NoMatchingProvider (0.13s)25092026/11/10 21:12:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53401/oidc2510--- PASS: TestPins_TopLevelShorthand (0.13s)25112026/11/10 21:12:34 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53403/oidc2512--- PASS: TestValidateToken_WrongAudience (0.15s)2513PASS2514Running hook tests...2515=== RUN TestSendPathsEmpty2516=== PAUSE TestSendPathsEmpty2517=== RUN TestQueueEnqueueAndFetch2518=== PAUSE TestQueueEnqueueAndFetch2519=== RUN TestQueueDeduplication2520=== PAUSE TestQueueDeduplication2521=== RUN TestQueueRemove2522=== PAUSE TestQueueRemove2523=== RUN TestQueueFetchBatchLimit2524=== PAUSE TestQueueFetchBatchLimit2525=== RUN TestQueueRetryMovesToBack2526=== PAUSE TestQueueRetryMovesToBack2527=== RUN TestQueueFetchRemoveLifecycle2528=== PAUSE TestQueueFetchRemoveLifecycle2529=== RUN TestQueueConcurrentWriters2530=== PAUSE TestQueueConcurrentWriters2531=== RUN TestQueueRemoveLargeClosure2532=== PAUSE TestQueueRemoveLargeClosure2533=== RUN TestServerClientIntegration2534--- PASS: TestServerClientIntegration (0.00s)2535=== RUN TestServerQueueError25362026/11/10 21:12:34 ERROR Failed to queue paths error="permission denied" count=12537--- PASS: TestServerQueueError (0.00s)2538=== RUN TestGetListenerSocketActivation2539 server_test.go:145: systemd socket activation does not exist on darwin2540--- SKIP: TestGetListenerSocketActivation (0.00s)2541=== RUN TestServerStalledClientDoesNotBlockShutdown2542=== PAUSE TestServerStalledClientDoesNotBlockShutdown2543=== RUN TestServerBacksOffOnAcceptErrors2544=== PAUSE TestServerBacksOffOnAcceptErrors2545=== RUN TestDrainIsolatesPoisonPath2546=== PAUSE TestDrainIsolatesPoisonPath2547=== RUN TestRunNotBlockedByPoisonHead2548=== PAUSE TestRunNotBlockedByPoisonHead2549=== RUN TestDrainGivesUpWhenServerDown2550=== PAUSE TestDrainGivesUpWhenServerDown2551=== RUN TestFailedPathPrunedByLaterClosure2552=== PAUSE TestFailedPathPrunedByLaterClosure2553=== RUN TestWorkerUploadsAndRemoves2554=== PAUSE TestWorkerUploadsAndRemoves2555=== RUN TestWorkerSkipsGCdPaths2556=== PAUSE TestWorkerSkipsGCdPaths2557=== RUN TestWorkerPrunesClosureDeps2558=== PAUSE TestWorkerPrunesClosureDeps2559=== RUN TestDrainTimeout2560=== PAUSE TestDrainTimeout2561=== RUN TestWorkerRemoveFailureIsNotProgress2562=== PAUSE TestWorkerRemoveFailureIsNotProgress2563=== RUN TestWorkerKeepsPathItCannotStat2564=== PAUSE TestWorkerKeepsPathItCannotStat2565=== CONT TestSendPathsEmpty2566=== CONT TestWorkerSkipsGCdPaths2567--- PASS: TestSendPathsEmpty (0.00s)2568=== CONT TestWorkerKeepsPathItCannotStat2569=== CONT TestWorkerRemoveFailureIsNotProgress2570=== CONT TestDrainTimeout2571=== CONT TestWorkerPrunesClosureDeps2572=== CONT TestDrainIsolatesPoisonPath2573=== CONT TestServerBacksOffOnAcceptErrors2574=== CONT TestServerStalledClientDoesNotBlockShutdown2575=== CONT TestQueueRemoveLargeClosure25762026/11/10 21:12:34 ERROR Accept failed error="too many open files"2577=== CONT TestQueueConcurrentWriters2578=== CONT TestQueueFetchRemoveLifecycle2579=== CONT TestQueueRetryMovesToBack2580=== CONT TestFailedPathPrunedByLaterClosure2581=== CONT TestQueueFetchBatchLimit2582=== CONT TestWorkerUploadsAndRemoves2583=== CONT TestQueueRemove2584=== CONT TestQueueDeduplication2585=== CONT TestQueueEnqueueAndFetch2586=== CONT TestDrainGivesUpWhenServerDown2587=== CONT TestRunNotBlockedByPoisonHead25882026/11/10 21:12:34 ERROR Accept failed error="too many open files"25892026/11/10 21:12:34 INFO Upload queue status pending=225902026/11/10 21:12:34 WARN Cannot stat store path, will retry later path=/private/var/tb/6/scratch/509dce1726107d78/build/TestWorkerKeepsPathItCannotStat3061349864/002/locked/aaa error="stat /private/var/tb/6/scratch/509dce1726107d78/build/TestWorkerKeepsPathItCannotStat3061349864/002/locked/aaa: permission denied"25912026/11/10 21:12:34 INFO Uploading batch count=125922026/11/10 21:12:34 INFO Upload queue status pending=325932026/11/10 21:12:34 INFO Uploading batch count=125942026/11/10 21:12:34 ERROR Upload failed error="upload failed" count=125952026/11/10 21:12:34 INFO Upload queue status pending=22596--- PASS: TestQueueEnqueueAndFetch (0.01s)25972026/11/10 21:12:34 INFO Uploading batch count=225982026/11/10 21:12:34 INFO Upload queue status pending=225992026/11/10 21:12:34 INFO Uploading batch count=426002026/11/10 21:12:34 ERROR Upload failed error="upload failed" count=426012026/11/10 21:12:34 INFO Uploading batch count=126022026/11/10 21:12:34 ERROR Upload failed error="upload failed" count=12603--- PASS: TestQueueFetchRemoveLifecycle (0.01s)26042026/11/10 21:12:34 WARN Cannot stat store path, will retry later path=/private/var/tb/6/scratch/509dce1726107d78/build/TestWorkerKeepsPathItCannotStat3061349864/002/locked/aaa error="stat /private/var/tb/6/scratch/509dce1726107d78/build/TestWorkerKeepsPathItCannotStat3061349864/002/locked/aaa: permission denied"26052026/11/10 21:12:34 INFO Uploading batch count=12606--- PASS: TestQueueDeduplication (0.01s)26072026/11/10 21:12:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/509dce1726107d78/build/TestDrainIsolatesPoisonPath1870878515/002/bbb26082026/11/10 21:12:34 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/509dce1726107d78/build/TestWorkerSkipsGCdPaths2685283108/002/nonexistent26092026/11/10 21:12:34 INFO Uploading batch count=226102026/11/10 21:12:34 INFO Uploading batch count=126112026/11/10 21:12:34 INFO Uploading batch count=12612--- PASS: TestQueueFetchBatchLimit (0.01s)26132026/11/10 21:12:34 INFO Uploading batch count=226142026/11/10 21:12:34 ERROR Upload failed error="upload failed" count=226152026/11/10 21:12:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/509dce1726107d78/build/TestDrainGivesUpWhenServerDown514005898/002/a26162026/11/10 21:12:34 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/509dce1726107d78/build/TestWorkerRemoveFailureIsNotProgress3114791067/002/nonexistent26172026/11/10 21:12:34 WARN Cannot stat store path, will retry later path=/private/var/tb/6/scratch/509dce1726107d78/build/TestWorkerKeepsPathItCannotStat3061349864/002/locked/aaa error="stat /private/var/tb/6/scratch/509dce1726107d78/build/TestWorkerKeepsPathItCannotStat3061349864/002/locked/aaa: permission denied"26182026/11/10 21:12:34 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126192026/11/10 21:12:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/509dce1726107d78/build/TestDrainGivesUpWhenServerDown514005898/002/b26202026/11/10 21:12:34 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/509dce1726107d78/build/TestWorkerRemoveFailureIsNotProgress3114791067/002/nonexistent26212026/11/10 21:12:34 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126222026/11/10 21:12:34 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/6/scratch/509dce1726107d78/build/TestWorkerRemoveFailureIsNotProgress3114791067/002/nonexistent26232026/11/10 21:12:34 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12624--- PASS: TestQueueRemove (0.01s)26252026/11/10 21:12:34 ERROR Accept failed error="too many open files"26262026/11/10 21:12:34 ERROR Drain finished with paths left in queue remaining=126272026/11/10 21:12:34 INFO Uploading batch count=226282026/11/10 21:12:34 ERROR Upload failed error="upload failed" count=226292026/11/10 21:12:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/509dce1726107d78/build/TestDrainGivesUpWhenServerDown514005898/002/c26302026/11/10 21:12:34 ERROR Drain finished with paths left in queue remaining=126312026/11/10 21:12:34 INFO Uploading batch count=126322026/11/10 21:12:34 ERROR Upload failed error="upload failed" count=126332026/11/10 21:12:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/509dce1726107d78/build/TestDrainGivesUpWhenServerDown514005898/002/d26342026/11/10 21:12:34 INFO Uploading batch count=126352026/11/10 21:12:34 ERROR Upload failed error="upload failed" count=126362026/11/10 21:12:34 INFO Uploading batch count=126372026/11/10 21:12:34 ERROR Upload failed error="upload failed" count=12638--- PASS: TestQueueRetryMovesToBack (0.02s)26392026/11/10 21:12:34 INFO Uploading batch count=226402026/11/10 21:12:34 ERROR Upload failed error="upload failed" count=226412026/11/10 21:12:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/509dce1726107d78/build/TestDrainGivesUpWhenServerDown514005898/002/e26422026/11/10 21:12:34 ERROR Drain finished with paths left in queue remaining=126432026/11/10 21:12:34 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/6/scratch/509dce1726107d78/build/TestDrainGivesUpWhenServerDown514005898/002/f2644--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)2645--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)26462026/11/10 21:12:34 ERROR Drain finished with paths left in queue remaining=102647--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2648--- PASS: TestDrainIsolatesPoisonPath (0.02s)2649--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2650--- PASS: TestWorkerPrunesClosureDeps (0.03s)2651--- PASS: TestWorkerUploadsAndRemoves (0.03s)2652--- PASS: TestWorkerSkipsGCdPaths (0.03s)26532026/11/10 21:12:34 ERROR Accept failed error="too many open files"2654--- PASS: TestQueueRemoveLargeClosure (0.05s)2655--- PASS: TestQueueConcurrentWriters (0.06s)26562026/11/10 21:12:35 ERROR Accept failed error="too many open files"26572026/11/10 21:12:35 ERROR Accept failed error="too many open files"26582026/11/10 21:12:35 ERROR Failed to decode request error="read unix /private/var/tb/6/scratch/509dce1726107d78/build/hook2766242888/test.sock->: i/o timeout"26592026/11/10 21:12:35 ERROR Failed to write response error="write unix /private/var/tb/6/scratch/509dce1726107d78/build/hook2766242888/test.sock->: i/o timeout"2660--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26612026/11/10 21:12:35 ERROR Upload failed error="context deadline exceeded" count=226622026/11/10 21:12:35 ERROR Drain finished with paths left in queue remaining=42663--- PASS: TestDrainTimeout (0.22s)26642026/11/10 21:12:35 ERROR Accept failed error="too many open files"26652026/11/10 21:12:35 ERROR Accept failed error="too many open files"2666--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26672026/11/10 21:12:35 INFO Uploading batch count=126682026/11/10 21:12:35 INFO Uploading batch count=126692026/11/10 21:12:35 INFO Uploading batch count=126702026/11/10 21:12:35 ERROR Upload failed error="upload failed" count=126712026/11/10 21:12:35 INFO Uploading batch count=126722026/11/10 21:12:35 ERROR Upload failed error="upload failed" count=126732026/11/10 21:12:35 INFO Uploading batch count=126742026/11/10 21:12:35 ERROR Upload failed error="upload failed" count=126752026/11/10 21:12:35 INFO Uploading batch count=126762026/11/10 21:12:35 ERROR Upload failed error="upload failed" count=126772026/11/10 21:12:35 ERROR Drain finished with paths left in queue remaining=12678--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2679PASS2680Running signing tests...2681=== RUN TestExternalSigner2682=== PAUSE TestExternalSigner2683=== RUN TestExternalSignerWrongPublicKey2684=== PAUSE TestExternalSignerWrongPublicKey2685=== RUN TestExternalSignerErrors2686=== PAUSE TestExternalSignerErrors2687=== RUN TestExternalSignerRestartsAfterCrash2688=== PAUSE TestExternalSignerRestartsAfterCrash2689=== RUN TestExternalSignerProgramErrorKeepsProcess2690=== PAUSE TestExternalSignerProgramErrorKeepsProcess2691=== RUN TestExternalSignerClose2692=== PAUSE TestExternalSignerClose2693=== RUN TestExternalSignerRejectsInvalidPublicKey2694=== PAUSE TestExternalSignerRejectsInvalidPublicKey2695=== RUN TestExternalSignerCancellation2696=== PAUSE TestExternalSignerCancellation2697=== RUN TestGenerateFingerprint2698=== PAUSE TestGenerateFingerprint2699=== RUN TestParseSigningKey2700=== PAUSE TestParseSigningKey2701=== RUN TestSign2702=== PAUSE TestSign2703=== RUN TestSignBatch2704=== PAUSE TestSignBatch2705=== RUN TestNilKeyPublicKey2706=== PAUSE TestNilKeyPublicKey2707=== RUN TestSignErrors2708=== PAUSE TestSignErrors2709=== RUN TestParsePublicKeysRejectsMalformed2710=== PAUSE TestParsePublicKeysRejectsMalformed2711=== CONT TestExternalSigner2712=== CONT TestGenerateFingerprint2713=== CONT TestNilKeyPublicKey2714=== RUN TestGenerateFingerprint/basic_with_references2715--- PASS: TestNilKeyPublicKey (0.00s)2716=== CONT TestParsePublicKeysRejectsMalformed2717--- PASS: TestParsePublicKeysRejectsMalformed (0.00s)2718=== PAUSE TestGenerateFingerprint/basic_with_references2719=== CONT TestSignBatch2720=== CONT TestSignErrors2721=== CONT TestSign2722=== CONT TestParseSigningKey2723=== RUN TestParseSigningKey/valid_32-byte_key2724=== CONT TestExternalSignerProgramErrorKeepsProcess2725=== CONT TestExternalSignerRejectsInvalidPublicKey2726=== RUN TestExternalSignerRejectsInvalidPublicKey/#002727=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002728=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2729=== CONT TestExternalSignerClose2730=== CONT TestExternalSignerCancellation2731=== CONT TestExternalSignerRestartsAfterCrash2732=== CONT TestExternalSignerWrongPublicKey2733=== CONT TestExternalSignerErrors2734=== RUN TestGenerateFingerprint/no_references2735=== PAUSE TestParseSigningKey/valid_32-byte_key2736=== PAUSE TestGenerateFingerprint/no_references2737=== RUN TestExternalSignerErrors/invalid_JSON2738=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2739=== PAUSE TestExternalSignerErrors/invalid_JSON2740=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2741=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2742=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2743=== RUN TestParseSigningKey/no_colon2744=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2745=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2746=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2747=== PAUSE TestParseSigningKey/no_colon2748=== RUN TestParseSigningKey/empty_name2749=== PAUSE TestParseSigningKey/empty_name2750=== RUN TestParseSigningKey/invalid_base642751=== PAUSE TestParseSigningKey/invalid_base642752=== RUN TestParseSigningKey/wrong_length2753=== PAUSE TestParseSigningKey/wrong_length2754=== CONT TestParseSigningKey/valid_32-byte_key2755=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2756=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2757=== RUN TestGenerateFingerprint/invalid_nar_hash_length2758=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2759=== RUN TestGenerateFingerprint/invalid_store_path_prefix2760=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2761=== RUN TestGenerateFingerprint/invalid_reference_prefix2762=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2763=== CONT TestGenerateFingerprint/basic_with_references2764=== CONT TestParseSigningKey/no_colon2765=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2766=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2767=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2768=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2769=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2770=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2771=== CONT TestGenerateFingerprint/invalid_store_path_prefix2772=== CONT TestParseSigningKey/empty_name2773=== CONT TestExternalSignerRejectsInvalidPublicKey/#002774=== CONT TestParseSigningKey/invalid_base642775=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2776=== CONT TestGenerateFingerprint/no_references2777=== RUN TestExternalSignerErrors/wrong_shape2778=== PAUSE TestExternalSignerErrors/wrong_shape2779=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2780=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2781=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2782=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2783--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2784 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2785 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2786 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2787 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2788 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2789=== CONT TestGenerateFingerprint/invalid_reference_prefix2790=== CONT TestGenerateFingerprint/invalid_nar_hash_length2791--- PASS: TestGenerateFingerprint (0.00s)2792 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2793 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2794 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2795 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2796 --- PASS: TestGenerateFingerprint/no_references (0.00s)2797 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2798 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2799=== CONT TestParseSigningKey/wrong_length2800=== RUN TestExternalSignerErrors/null2801=== PAUSE TestExternalSignerErrors/null2802=== RUN TestExternalSignerErrors/wrong_id2803=== PAUSE TestExternalSignerErrors/wrong_id2804=== RUN TestExternalSignerErrors/invalid_signature_base642805=== PAUSE TestExternalSignerErrors/invalid_signature_base642806=== RUN TestExternalSignerErrors/program_error2807=== PAUSE TestExternalSignerErrors/program_error2808=== RUN TestExternalSignerErrors/exit_on_request2809=== PAUSE TestExternalSignerErrors/exit_on_request2810=== RUN TestExternalSignerErrors/null_signatures2811=== PAUSE TestExternalSignerErrors/null_signatures2812=== RUN TestExternalSignerErrors/too_few_signatures2813=== PAUSE TestExternalSignerErrors/too_few_signatures2814=== RUN TestExternalSignerErrors/unrequested_key2815=== PAUSE TestExternalSignerErrors/unrequested_key2816=== RUN TestExternalSignerErrors/wrong_signature_name2817=== PAUSE TestExternalSignerErrors/wrong_signature_name2818=== RUN TestExternalSignerErrors/missing_signature_name2819=== PAUSE TestExternalSignerErrors/missing_signature_name2820=== RUN TestExternalSignerErrors/exit_at_startup2821=== PAUSE TestExternalSignerErrors/exit_at_startup2822=== RUN TestExternalSignerErrors/missing_signatures2823=== PAUSE TestExternalSignerErrors/missing_signatures2824=== RUN TestExternalSignerErrors/wrong_signatures_shape2825=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2826=== RUN TestExternalSignerErrors/wrong_signature_length2827=== PAUSE TestExternalSignerErrors/wrong_signature_length2828=== CONT TestExternalSignerErrors/invalid_JSON2829--- PASS: TestSign (0.00s)2830--- PASS: TestParseSigningKey (0.00s)2831 --- PASS: TestParseSigningKey/no_colon (0.00s)2832 --- PASS: TestParseSigningKey/empty_name (0.00s)2833 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2834 --- PASS: TestParseSigningKey/wrong_length (0.00s)2835 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2836 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2837=== CONT TestExternalSignerErrors/exit_at_startup2838=== CONT TestExternalSignerErrors/exit_on_request2839=== CONT TestExternalSignerErrors/missing_signature_name2840=== CONT TestExternalSignerErrors/invalid_signature_base642841=== RUN TestSignErrors/nil_key2842=== PAUSE TestSignErrors/nil_key2843=== CONT TestExternalSignerErrors/wrong_signature_name2844=== CONT TestExternalSignerErrors/wrong_shape2845=== CONT TestExternalSignerErrors/wrong_signatures_shape2846=== CONT TestExternalSignerErrors/missing_signatures2847=== CONT TestExternalSignerErrors/null2848=== CONT TestExternalSignerErrors/program_error2849=== CONT TestExternalSignerErrors/too_few_signatures2850=== CONT TestExternalSignerErrors/null_signatures2851--- PASS: TestSignBatch (0.00s)2852=== CONT TestExternalSignerErrors/wrong_signature_length2853=== RUN TestSignErrors/nil_narinfo2854=== CONT TestExternalSignerErrors/wrong_id2855=== CONT TestExternalSignerErrors/unrequested_key2856=== PAUSE TestSignErrors/nil_narinfo2857=== RUN TestSignErrors/invalid_narinfo2858=== PAUSE TestSignErrors/invalid_narinfo2859=== RUN TestSignErrors/canceled2860=== PAUSE TestSignErrors/canceled2861=== CONT TestSignErrors/nil_key2862=== CONT TestSignErrors/canceled2863=== CONT TestSignErrors/invalid_narinfo2864=== CONT TestSignErrors/nil_narinfo2865--- PASS: TestSignErrors (0.01s)2866 --- PASS: TestSignErrors/nil_key (0.00s)2867 --- PASS: TestSignErrors/canceled (0.00s)2868 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2869 --- PASS: TestSignErrors/nil_narinfo (0.00s)2870--- PASS: TestExternalSigner (0.23s)2871--- PASS: TestExternalSignerClose (0.40s)2872--- PASS: TestExternalSignerWrongPublicKey (0.59s)2873--- PASS: TestExternalSignerRestartsAfterCrash (1.37s)2874/private/var/tb/6/scratch/509dce1726107d78/build/TestExternalSignerRestartsAfterCrash4222154155/001/sign program: line 7: /private/var/tb/6/scratch/509dce1726107d78/build/TestExternalSignerRestartsAfterCrash4222154155/001/sign program.starts: No such file or directory2875--- PASS: TestExternalSignerProgramErrorKeepsProcess (2.09s)2876--- PASS: TestExternalSignerCancellation (2.30s)2877--- PASS: TestExternalSignerErrors (0.00s)2878 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.78s)2879 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.96s)2880 --- PASS: TestExternalSignerErrors/unrequested_key (1.16s)2881 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.53s)2882 --- PASS: TestExternalSignerErrors/missing_signature_name (1.72s)2883 --- PASS: TestExternalSignerErrors/missing_signatures (1.90s)2884 --- PASS: TestExternalSignerErrors/exit_on_request (2.56s)2885 --- PASS: TestExternalSignerErrors/null (2.75s)2886 --- PASS: TestExternalSignerErrors/invalid_JSON (2.94s)2887 --- PASS: TestExternalSignerErrors/wrong_shape (3.15s)2888 --- PASS: TestExternalSignerErrors/wrong_id (3.35s)2889 --- PASS: TestExternalSignerErrors/too_few_signatures (3.53s)2890 --- PASS: TestExternalSignerErrors/wrong_signature_length (3.72s)2891 --- PASS: TestExternalSignerErrors/exit_at_startup (3.91s)2892 --- PASS: TestExternalSignerErrors/program_error (4.09s)2893 --- PASS: TestExternalSignerErrors/null_signatures (4.28s)2894PASS2895Running OpenBao signer tests...2896=== RUN TestSign2897=== PAUSE TestSign2898=== RUN TestSignErrors2899=== PAUSE TestSignErrors2900=== RUN TestServe2901=== PAUSE TestServe2902=== RUN TestServeRejectsGarbage2903=== PAUSE TestServeRejectsGarbage2904=== CONT TestSign2905=== CONT TestSignErrors2906=== RUN TestSignErrors/http_error2907=== PAUSE TestSignErrors/http_error2908=== RUN TestSignErrors/invalid_json2909=== PAUSE TestSignErrors/invalid_json2910=== RUN TestSignErrors/no_prefix2911=== PAUSE TestSignErrors/no_prefix2912=== CONT TestServeRejectsGarbage2913--- PASS: TestServeRejectsGarbage (0.00s)2914=== CONT TestServe2915=== RUN TestSignErrors/invalid_base642916=== PAUSE TestSignErrors/invalid_base642917=== CONT TestSignErrors/http_error2918=== CONT TestSignErrors/no_prefix2919=== CONT TestSignErrors/invalid_base642920=== CONT TestSignErrors/invalid_json2921--- PASS: TestServe (0.00s)2922--- PASS: TestSignErrors (0.00s)2923 --- PASS: TestSignErrors/invalid_json (0.00s)2924 --- PASS: TestSignErrors/http_error (0.00s)2925 --- PASS: TestSignErrors/no_prefix (0.00s)2926 --- PASS: TestSignErrors/invalid_base64 (0.00s)2927--- PASS: TestSign (0.00s)2928PASS