niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #466
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_ReturnsAfterDroppedBody20=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestDumpPathCaseHackMatchesNix24--- PASS: TestDumpPathCaseHackMatchesNix (0.08s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== RUN TestDumpPathMatchesNix28=== PAUSE TestDumpPathMatchesNix29=== RUN TestDumpPathSingleFile30=== PAUSE TestDumpPathSingleFile31=== RUN TestDumpPathWriterError32=== PAUSE TestDumpPathWriterError33=== RUN TestEncodeNixBase3234=== PAUSE TestEncodeNixBase3235=== RUN TestEncodeNixBase32WithRealHash36=== PAUSE TestEncodeNixBase32WithRealHash37=== RUN TestConvertHashToNix3238=== PAUSE TestConvertHashToNix3239=== RUN TestGetStorePathHash40=== PAUSE TestGetStorePathHash41=== RUN TestPathInfoHashCompatibility42=== PAUSE TestPathInfoHashCompatibility43=== RUN TestParsePathInfoJSON44=== PAUSE TestParsePathInfoJSON45=== RUN TestParsePathInfoJSONMultiplePaths46=== PAUSE TestParsePathInfoJSONMultiplePaths47=== RUN TestPathInfoCACompatibility48=== PAUSE TestPathInfoCACompatibility49=== RUN TestRateLimiterFeedback50=== PAUSE TestRateLimiterFeedback51=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess52=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess53=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer54=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer55=== RUN TestResolveStorePath56=== PAUSE TestResolveStorePath57=== RUN TestDoWithRetry_BodyReplayedViaGetBody58=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody59=== RUN TestRetryTimeoutOutlastsMaxRetries60=== PAUSE TestRetryTimeoutOutlastsMaxRetries61=== RUN TestDoWithRetry_FinalResponseBodyReadable62=== PAUSE TestDoWithRetry_FinalResponseBodyReadable63=== RUN TestShellSplit64=== PAUSE TestShellSplit65=== RUN TestShellSplitErrors66=== PAUSE TestShellSplitErrors67=== RUN TestStreamPushReportsEveryPath68=== PAUSE TestStreamPushReportsEveryPath69=== RUN TestStreamPushBatchesUnderLoad70=== PAUSE TestStreamPushBatchesUnderLoad71=== RUN TestStreamPushIsolatesFailures72=== PAUSE TestStreamPushIsolatesFailures73=== RUN TestStreamPushGivesUpOnDeadServer74=== PAUSE TestStreamPushGivesUpOnDeadServer75=== RUN TestStreamPushRequestLine76=== PAUSE TestStreamPushRequestLine77=== RUN TestStreamPushReportsSignatures78=== PAUSE TestStreamPushReportsSignatures79=== RUN TestStreamPushReportsSkippedPaths80=== PAUSE TestStreamPushReportsSkippedPaths81=== RUN TestClientSignaturesByStorePath82=== PAUSE TestClientSignaturesByStorePath83=== RUN TestStreamPushStopsWhenCanceled84=== PAUSE TestStreamPushStopsWhenCanceled85=== RUN TestSetClientTLS86=== PAUSE TestSetClientTLS87=== RUN TestSetClientTLSDoesNotMutateDefaultTransport88=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport89=== RUN TestSetClientTLSErrors90=== PAUSE TestSetClientTLSErrors91=== RUN TestStaticToken92=== PAUSE TestStaticToken93=== RUN TestFileTokenReadsAndCaches94=== PAUSE TestFileTokenReadsAndCaches95=== RUN TestFileTokenMissing96=== PAUSE TestFileTokenMissing97=== RUN TestFileTokenEmpty98=== PAUSE TestFileTokenEmpty99=== RUN TestScriptTokenNoExpiryRerunsEveryCall100=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall101=== RUN TestScriptTokenCachesUntilRefresh102=== PAUSE TestScriptTokenCachesUntilRefresh103=== RUN TestScriptTokenEmptyToken104=== PAUSE TestScriptTokenEmptyToken105=== RUN TestScriptTokenBadJSON106=== PAUSE TestScriptTokenBadJSON107=== RUN TestScriptTokenScriptFails108=== PAUSE TestScriptTokenScriptFails109=== RUN TestScriptTokenEmptyCommand110=== PAUSE TestScriptTokenEmptyCommand111=== CONT TestDoServerRequestAttachesToken112=== CONT TestRetryTimeoutOutlastsMaxRetries113=== CONT TestSetClientTLS114=== CONT TestStreamPushReportsSignatures115=== CONT TestStreamPushIsolatesFailures116=== CONT TestStreamPushRequestLine117=== CONT TestStreamPushBatchesUnderLoad118=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false119=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false120=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true121=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true122=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false123=== CONT TestEncodeNixBase32124=== RUN TestEncodeNixBase32/test_string_hash125=== PAUSE TestEncodeNixBase32/test_string_hash126=== RUN TestEncodeNixBase32/empty_input127=== PAUSE TestEncodeNixBase32/empty_input128=== CONT TestDoWithRetry_BodyReplayedViaGetBody129=== CONT TestStreamPushReportsEveryPath1302026/11/06 07:44:09 ERROR Upload failed error="bad path" count=3131=== CONT TestResolveStorePath132=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer133=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess134=== CONT TestRateLimiterFeedback135=== CONT TestPathInfoCACompatibility136=== CONT TestParsePathInfoJSONMultiplePaths137=== CONT TestParsePathInfoJSON138=== CONT TestPathInfoHashCompatibility139=== CONT TestGetStorePathHash140=== CONT TestConvertHashToNix32141=== CONT TestEncodeNixBase32WithRealHash142=== CONT TestStreamPushGivesUpOnDeadServer143=== CONT TestStreamPushStopsWhenCanceled144=== CONT TestClientSignaturesByStorePath145=== CONT TestStreamPushReportsSkippedPaths146=== RUN TestPathInfoCACompatibility/null_ca_field1472026/11/06 07:44:09 WARN Rate limiter enabled after throttle name=server-test rate=5148--- PASS: TestStreamPushReportsEveryPath (0.00s)149=== CONT TestShellSplitErrors1502026/11/06 07:44:09 ERROR Upload failed error="connection refused" count=201512026/11/06 07:44:09 ERROR Server seems unavailable, giving up on batch untried=17152=== RUN TestRateLimiterFeedback/429_enables_limiter153=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths154=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths155=== PAUSE TestRateLimiterFeedback/429_enables_limiter156=== RUN TestConvertHashToNix32/SRI_format_to_Nix32157=== RUN TestRateLimiterFeedback/503_enables_limiter158=== CONT TestDoWithRetry_FinalResponseBodyReadable159=== PAUSE TestRateLimiterFeedback/503_enables_limiter160=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter161=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter162=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter163=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter164=== RUN TestParsePathInfoJSON/Nix_format165=== PAUSE TestParsePathInfoJSON/Nix_format166=== RUN TestParsePathInfoJSON/Lix_format167=== PAUSE TestParsePathInfoJSON/Lix_format168=== RUN TestParsePathInfoJSON/empty_input169=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true170=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32171=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths172=== CONT TestDumpPathWriterError1732026/11/06 07:44:09 ERROR Upload failed error=boom count=1174--- PASS: TestEncodeNixBase32WithRealHash (0.00s)1752026/11/06 07:44:09 ERROR Upload failed error=boom count=1176--- PASS: TestStreamPushReportsSignatures (0.00s)177--- PASS: TestStreamPushReportsSkippedPaths (0.00s)178=== CONT TestScriptTokenEmptyCommand179--- PASS: TestScriptTokenEmptyCommand (0.00s)180=== CONT TestScriptTokenBadJSON181=== CONT TestShellSplit1822026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:558001832026/11/06 07:44:09 WARN Rate limiter enabled after throttle name=server-test rate=5184=== RUN TestGetStorePathHash/valid_store_path1852026/11/06 07:44:09 WARN Rate limiter enabled after throttle name=server-test rate=51862026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55801187=== CONT TestDumpPathMatchesNix1882026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:558101892026/11/06 07:44:09 WARN Rate limiter backed off name=server-test rate=51902026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:558001912026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:55801192=== PAUSE TestParsePathInfoJSON/empty_input193=== RUN TestParsePathInfoJSON/whitespace_only194=== PAUSE TestParsePathInfoJSON/whitespace_only195=== RUN TestParsePathInfoJSON/invalid_JSON196=== PAUSE TestParsePathInfoJSON/invalid_JSON197=== RUN TestConvertHashToNix32/already_Nix32_format198=== PAUSE TestConvertHashToNix32/already_Nix32_format199=== RUN TestConvertHashToNix32/invalid_format200=== PAUSE TestConvertHashToNix32/invalid_format201=== CONT TestSetClientTLSErrors2022026/11/06 07:44:09 WARN Rate limiter backed off name=server-test rate=5203=== CONT TestStaticToken204=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry205=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths206=== CONT TestDumpPathSingleFile207=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica208=== RUN TestSetClientTLSErrors/missing_cert_file209=== PAUSE TestSetClientTLSErrors/missing_cert_file210=== RUN TestSetClientTLSErrors/missing_key_file211=== PAUSE TestSetClientTLSErrors/missing_key_file212=== RUN TestSetClientTLSErrors/missing_ca_file213=== PAUSE TestSetClientTLSErrors/missing_ca_file214=== RUN TestSetClientTLSErrors/invalid_ca_file215=== PAUSE TestSetClientTLSErrors/invalid_ca_file216=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun217=== CONT TestScriptTokenNoExpiryRerunsEveryCall218=== PAUSE TestPathInfoCACompatibility/null_ca_field219=== RUN TestPathInfoCACompatibility/old_string_format_-_text220=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text221=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive222=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive223=== RUN TestPathInfoCACompatibility/new_structured_format_-_text224=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text225=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method226=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method227--- PASS: TestStreamPushStopsWhenCanceled (0.00s)228=== CONT TestSetClientTLSDoesNotMutateDefaultTransport229--- PASS: TestShellSplitErrors (0.00s)230--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)231--- PASS: TestStreamPushIsolatesFailures (0.00s)232--- PASS: TestClientSignaturesByStorePath (0.00s)233--- PASS: TestShellSplit (0.00s)234--- PASS: TestResolveStorePath (0.00s)235--- PASS: TestDoServerRequestAttachesToken (0.00s)236=== CONT TestScriptTokenEmptyToken237--- PASS: TestStaticToken (0.00s)238--- PASS: TestStreamPushBatchesUnderLoad (0.00s)239 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)240 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)241--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)242=== CONT TestScriptTokenScriptFails243--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)244=== CONT TestCaseHackSuffix2452026/11/06 07:44:09 INFO Garbage collection started2462026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:55800247=== CONT TestFileTokenReadsAndCaches248=== CONT TestFileTokenEmpty249=== CONT TestScriptTokenCachesUntilRefresh2502026/11/06 07:44:09 INFO Garbage collection started2512026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:55800252=== PAUSE TestGetStorePathHash/valid_store_path253=== RUN TestGetStorePathHash/basename_without_hyphen_should_error254=== CONT TestFileTokenMissing255=== CONT TestFilterOversizedClosures256=== RUN TestFilterOversizedClosures/no_limit_keeps_everything257=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything258=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped259=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped260=== RUN TestFilterOversizedClosures/all_closures_skipped261=== PAUSE TestFilterOversizedClosures/all_closures_skipped262=== CONT TestEncodeNixBase32/test_string_hash263=== CONT TestEncodeNixBase32/empty_input264=== CONT TestRateLimiterFeedback/429_enables_limiter265=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error266=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error267=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error268=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error269=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error270=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter271=== CONT TestRegisterUploadedObjectReusesConnections272=== RUN TestSetClientTLS/rejects_connection_without_client_cert2732026/11/06 07:44:09 WARN Rate limiter enabled after throttle name=s3-test rate=52742026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55818275=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert276=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA277=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)278--- PASS: TestFileTokenEmpty (0.00s)279--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)280--- PASS: TestScriptTokenScriptFails (0.00s)281--- PASS: TestFileTokenReadsAndCaches (0.01s)282=== CONT TestUploadMultipart_ReturnsAfterDroppedBody283=== CONT TestPartSizeForNAR284=== CONT TestUploadMultipart_PartsInParallel285--- PASS: TestScriptTokenBadJSON (0.01s)286--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)287=== CONT TestRateLimiterFeedback/503_enables_limiter2882026/11/06 07:44:09 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=0289=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA290=== RUN TestSetClientTLS/preserves_debug_logging_transport291=== PAUSE TestSetClientTLS/preserves_debug_logging_transport292=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)293=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon294=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon295=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI296=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI297=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512298=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512299=== CONT TestParsePathInfoJSON/Nix_format300=== CONT TestConvertHashToNix32/SRI_format_to_Nix32301=== CONT TestParsePathInfoJSON/invalid_JSON302=== CONT TestParsePathInfoJSON/empty_input303=== CONT TestParsePathInfoJSON/Lix_format304=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter305=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths306=== CONT TestConvertHashToNix32/invalid_format307--- PASS: TestEncodeNixBase32 (0.00s)308 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)309 --- PASS: TestEncodeNixBase32/empty_input (0.00s)310=== CONT TestParsePathInfoJSON/whitespace_only311--- PASS: TestParsePathInfoJSON (0.00s)312 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)313 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)314 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)315 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)316 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)317=== CONT TestConvertHashToNix32/already_Nix32_format318--- PASS: TestStreamPushRequestLine (0.02s)319=== CONT TestSetClientTLSErrors/invalid_ca_file320--- PASS: TestScriptTokenEmptyToken (0.02s)321=== CONT TestSetClientTLSErrors/missing_ca_file322=== CONT TestSetClientTLSErrors/missing_key_file323=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths324--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)325 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)326 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)327=== CONT TestPathInfoCACompatibility/null_ca_field328=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive329=== CONT TestPathInfoCACompatibility/old_string_format_-_text330=== CONT TestPathInfoCACompatibility/new_structured_format_-_text331=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method332--- PASS: TestPathInfoCACompatibility (0.01s)333 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)334 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)335 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)336 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)337 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)338=== CONT TestFilterOversizedClosures/no_limit_keeps_everything339=== CONT TestFilterOversizedClosures/all_closures_skipped340=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3412026/11/06 07:44:09 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50342=== CONT TestGetStorePathHash/valid_store_path3432026/11/06 07:44:09 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=2000344--- PASS: TestFilterOversizedClosures (0.00s)345 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)346 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)347 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)348=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error349=== CONT TestGetStorePathHash/basename_without_hyphen_should_error350=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error351--- PASS: TestGetStorePathHash (0.01s)352 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)353 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)354 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)355 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)356=== CONT TestSetClientTLS/rejects_connection_without_client_cert357=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)358=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512359=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI360=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon361--- PASS: TestPathInfoHashCompatibility (0.02s)362 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)363 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)364 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)365 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)366=== CONT TestSetClientTLS/preserves_debug_logging_transport367=== RUN TestPartSizeForNAR/zero_stays_at_minimum368=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum369=== RUN TestPartSizeForNAR/small_stays_at_minimum370=== PAUSE TestPartSizeForNAR/small_stays_at_minimum371=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum372=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum373=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts374=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts375=== RUN TestPartSizeForNAR/1_TiB376=== PAUSE TestPartSizeForNAR/1_TiB377=== RUN TestPartSizeForNAR/5_TiB_S3_max_object378=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object379=== RUN TestPartSizeForNAR/capped_at_5_GiB380=== PAUSE TestPartSizeForNAR/capped_at_5_GiB381=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA382=== CONT TestPartSizeForNAR/zero_stays_at_minimum383=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum384=== CONT TestPartSizeForNAR/capped_at_5_GiB385=== CONT TestPartSizeForNAR/5_TiB_S3_max_object386=== CONT TestPartSizeForNAR/1_TiB387=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts388=== CONT TestPartSizeForNAR/small_stays_at_minimum389--- PASS: TestPartSizeForNAR (0.01s)390 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)391 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)392 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)393 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)394 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)395 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)396 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)3972026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:55800398--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.03s)399--- PASS: TestConvertHashToNix32 (0.00s)400 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)401 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)402 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)403=== CONT TestSetClientTLSErrors/missing_cert_file4042026/11/06 07:44:09 WARN Garbage collection finished on another replica. Its statistics are not available here405--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.03s)406--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.02s)407--- PASS: TestFileTokenMissing (0.02s)4082026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:55800409--- PASS: TestSetClientTLSErrors (0.00s)410 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)411 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)412 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)413 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)4142026/11/06 07:44:09 WARN Rate limiter enabled after throttle name=server-test rate=54152026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:558254162026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:558004172026/11/06 07:44:09 WARN Rate limiter enabled after throttle name=server-test rate=54182026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:558204192026/11/06 07:44:09 WARN Rate limiter backed off name=server-test rate=54202026/11/06 07:44:09 WARN Rate limiter backed off name=server-test rate=5421--- PASS: TestRateLimiterFeedback (0.00s)422 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)423 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.02s)424 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.03s)425 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.03s)4262026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:558004272026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:558004282026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:558004292026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:558004302026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:558004312026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:558004322026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:558004332026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:558004342026/11/06 07:44:09 http: TLS handshake error from 127.0.0.1:55863: remote error: tls: bad certificate435--- PASS: TestSetClientTLS (0.02s)436 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)437 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)438 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)4392026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:558004402026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:558004412026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:55800442--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)4432026/11/06 07:44:09 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:55800444--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)445--- PASS: TestDumpPathSingleFile (0.06s)446--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.06s)447--- PASS: TestScriptTokenCachesUntilRefresh (0.06s)448--- PASS: TestDumpPathWriterError (0.07s)449--- PASS: TestCaseHackSuffix (0.07s)450--- PASS: TestDumpPathMatchesNix (0.09s)451--- PASS: TestUploadMultipart_PartsInParallel (0.62s)4522026/11/06 07:44:10 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55802/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55802/api/uploads/complete4532026/11/06 07:44:10 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"454--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4552026/11/06 07:44:10 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55802/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55802/api/uploads/complete4562026/11/06 07:44:10 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4572026/11/06 07:44:10 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55802/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55802/api/uploads/complete4582026/11/06 07:44:10 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"459--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)460PASS461Running server tests...462The files belonging to this database system will be owned by user "_tribuchetbld3".463This user must also own the server process.464465The database cluster will be initialized with locale "C".466The default database encoding has accordingly been set to "SQL_ASCII".467The default text search configuration will be set to "english".468469Data page checksums are enabled.470471creating directory /private/var/tb/3/scratch/230fe8f1ab4df694/build/postgres2027732289/data ... ok472creating subdirectories ... ok473selecting dynamic shared memory implementation ... posix474selecting default "max_connections" ... 100475selecting default "shared_buffers" ... 128MB476selecting default time zone ... UTC477creating configuration files ... ok478running bootstrap script ... ok479performing post-bootstrap initialization ... ok480syncing data to disk ... ok481482initdb: warning: enabling "trust" authentication for local connections483initdb: 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.484485Success. You can now start the database server using:486487 pg_ctl -D /private/var/tb/3/scratch/230fe8f1ab4df694/build/postgres2027732289/data -l logfile start488489/private/var/tb/3/scratch/230fe8f1ab4df694/build/postgres2027732289:5432 - no response4902026-11-06 07:44:11.153 UTC [94627] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4912026-11-06 07:44:11.153 UTC [94627] LOG: listening on Unix socket "/private/var/tb/3/scratch/230fe8f1ab4df694/build/postgres2027732289/.s.PGSQL.5432"4922026-11-06 07:44:11.156 UTC [94634] LOG: database system was shut down at 2026-11-06 07:44:11 UTC4932026-11-06 07:44:11.157 UTC [94627] LOG: database system is ready to accept connections494/private/var/tb/3/scratch/230fe8f1ab4df694/build/postgres2027732289:5432 - accepting connections495{"timestamp":"2026-11-06T07:44:11.494168Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"25925eed-a7b6-4b47-bce5-8deb7212c7f3","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":7,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}496{"timestamp":"2026-11-06T07:44:11.605883Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"e524a246-6a97-423b-b481-06a18f738835","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}497{"timestamp":"2026-11-06T07:44:11.709623Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"0f710f51-36d3-4e5d-8354-4da9b11734c9","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)"}498{"timestamp":"2026-11-06T07:44:11.813466Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"aed4b13a-21d9-46ee-9ee8-b2f766a10f8c","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}499=== RUN TestAbortSucceeded500=== PAUSE TestAbortSucceeded501=== RUN TestService_AuthMiddleware502=== PAUSE TestService_AuthMiddleware503=== RUN TestService_AuthMiddleware_MTLSProxyHeader504=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader505=== RUN TestService_AuthMiddleware_MTLSBoundSubjects506=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects507=== RUN TestService_ReadAuthMiddleware508=== PAUSE TestService_ReadAuthMiddleware509=== RUN TestService_AuthMiddleware_OIDC510=== PAUSE TestService_AuthMiddleware_OIDC511=== RUN TestService_RequireScope_OIDC512=== PAUSE TestService_RequireScope_OIDC513=== RUN TestService_ReadScope_PublicByDefault514=== PAUSE TestService_ReadScope_PublicByDefault515=== RUN TestCacheConfigHandler516=== PAUSE TestCacheConfigHandler517=== RUN TestCacheStatsHandler518=== PAUSE TestCacheStatsHandler519=== RUN TestClientCADerivations520=== PAUSE TestClientCADerivations521=== RUN TestClientErrorHandling522=== PAUSE TestClientErrorHandling523=== RUN TestClientIntegration524=== PAUSE TestClientIntegration525=== RUN TestClientMultipleUploads526=== PAUSE TestClientMultipleUploads527=== RUN TestClientWithDependencies528=== PAUSE TestClientWithDependencies529=== RUN TestClientSharedPathCommittedMidPush530=== PAUSE TestClientSharedPathCommittedMidPush531=== RUN TestPinProtectsFromGC532=== PAUSE TestPinProtectsFromGC533=== RUN TestClientPushesUseOnePush534=== PAUSE TestClientPushesUseOnePush535=== RUN TestClientFallsBackToClosures536=== PAUSE TestClientFallsBackToClosures537=== RUN TestDeleteClosuresRacingPins538=== PAUSE TestDeleteClosuresRacingPins539=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock540=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock541=== RUN TestResolveDBConnectionString542=== PAUSE TestResolveDBConnectionString543=== RUN TestConnectWaitsForAPeerMigration544=== PAUSE TestConnectWaitsForAPeerMigration545=== RUN TestLeadElectsOneAndHandsOver546=== PAUSE TestLeadElectsOneAndHandsOver547=== RUN TestLeadIncumbentWinsAfterRestart5482026/11/06 07:44:12 INFO lead: acquired remote=192.0.2.1:12345492026/11/06 07:44:12 INFO lead: released remote=192.0.2.1:12345502026/11/06 07:44:12 INFO lead: acquired remote=192.0.2.1:12345512026/11/06 07:44:13 INFO lead: released remote=192.0.2.1:1234552--- PASS: TestLeadIncumbentWinsAfterRestart (1.94s)553=== RUN TestLeadIncumbentAnnouncesAtOnce554=== PAUSE TestLeadIncumbentAnnouncesAtOnce555=== RUN TestLeadEndsOnShutdown556=== PAUSE TestLeadEndsOnShutdown557=== RUN TestLeadEndsWhenItsConnectionHangs5582026/11/06 07:44:13 INFO lead: acquired remote=192.0.2.1:12345592026-11-06 07:44:15.397 UTC [94685] FATAL: terminating connection due to administrator command5602026/11/06 07:44:15 INFO lead: acquired remote=192.0.2.1:12345612026/11/06 07:44:16 WARN lead: lock connection lost error="timeout: context deadline exceeded"5622026/11/06 07:44:16 INFO lead: released remote=192.0.2.1:12345632026/11/06 07:44:16 INFO lead: released remote=192.0.2.1:1234564--- PASS: TestLeadEndsWhenItsConnectionHangs (2.93s)565=== RUN TestGCAdvisoryLockBlocksConcurrentRun566=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun567=== RUN TestGCBugBareHashReferences568=== PAUSE TestGCBugBareHashReferences569=== RUN TestGCMetrics570=== PAUSE TestGCMetrics571=== RUN TestPushDedupSurvivesConcurrentGC572=== PAUSE TestPushDedupSurvivesConcurrentGC573=== RUN TestDeduplicatedObjectsRecordedAsPending574=== PAUSE TestDeduplicatedObjectsRecordedAsPending575=== RUN TestGCSweepSkipsPendingObjects576=== PAUSE TestGCSweepSkipsPendingObjects577=== RUN TestTombstonedObjectOfferedWithoutWaiting578=== PAUSE TestTombstonedObjectOfferedWithoutWaiting579=== RUN TestGCSweepDeliversEachKeyOnce580=== PAUSE TestGCSweepDeliversEachKeyOnce581=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection582=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection583=== RUN TestForceGCDuringPushOffersSweptObject584=== PAUSE TestForceGCDuringPushOffersSweptObject585=== RUN TestFailedS3DeleteKeepsTombstone586=== PAUSE TestFailedS3DeleteKeepsTombstone587=== RUN TestSweepSkipsRowsLockedByPush588=== PAUSE TestSweepSkipsRowsLockedByPush589=== RUN TestRegisterCompletedObjectNeedsPendingRow590=== PAUSE TestRegisterCompletedObjectNeedsPendingRow591=== RUN TestGetExistingObjectsLocksRows592=== PAUSE TestGetExistingObjectsLocksRows593=== RUN TestSweepRechecksPendingAfterLocking594=== PAUSE TestSweepRechecksPendingAfterLocking595=== RUN TestPushWaitsForSweepHoldingRow596=== PAUSE TestPushWaitsForSweepHoldingRow597=== RUN TestCommitRacingPendingCleanupKeepsObjects598=== PAUSE TestCommitRacingPendingCleanupKeepsObjects599=== RUN TestGCEndsOnShutdown600=== PAUSE TestGCEndsOnShutdown601=== RUN TestGCTaskStore_StartNew602=== PAUSE TestGCTaskStore_StartNew603=== RUN TestGCTaskStore_DeduplicateSameParams604=== PAUSE TestGCTaskStore_DeduplicateSameParams605=== RUN TestGCTaskStore_ConflictDifferentParams606=== PAUSE TestGCTaskStore_ConflictDifferentParams607=== RUN TestGCTaskStore_GetEmpty608=== PAUSE TestGCTaskStore_GetEmpty609=== RUN TestGCTaskStore_GetReturnsLatest610=== PAUSE TestGCTaskStore_GetReturnsLatest611=== RUN TestGCTaskStore_CompletedAllowsNewTask612=== PAUSE TestGCTaskStore_CompletedAllowsNewTask613=== RUN TestGCTaskStore_PhaseUpdates614=== PAUSE TestGCTaskStore_PhaseUpdates615=== RUN TestGCTaskStore_Fail616=== PAUSE TestGCTaskStore_Fail617=== RUN TestGracefulShutdownDrainsInflight618=== PAUSE TestGracefulShutdownDrainsInflight619=== RUN TestService_healthCheckHandler620=== PAUSE TestService_healthCheckHandler621=== RUN TestService_readinessHandler622=== PAUSE TestService_readinessHandler623=== RUN TestGenerateLandingPage624=== PAUSE TestGenerateLandingPage625=== RUN TestEnsureAbortUploadsRule626=== PAUSE TestEnsureAbortUploadsRule627=== RUN TestCacheConfigHandlerMaxNarSize628=== PAUSE TestCacheConfigHandlerMaxNarSize629=== RUN TestCreatePendingClosureRejectsOversizedNAR630=== PAUSE TestCreatePendingClosureRejectsOversizedNAR631=== RUN TestNARDeduplicationMetadataUploadBug632=== PAUSE TestNARDeduplicationMetadataUploadBug633=== RUN TestMetricsInventory634=== PAUSE TestMetricsInventory635=== RUN TestMetricsCommit636=== PAUSE TestMetricsCommit637=== RUN TestService_NativeMTLS638=== PAUSE TestService_NativeMTLS639=== RUN TestServerTLSConfig640=== PAUSE TestServerTLSConfig641=== RUN TestMultipartCleanup642=== PAUSE TestMultipartCleanup643=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded644=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded645=== RUN TestPendingCleanupUsesOneCutoff646=== PAUSE TestPendingCleanupUsesOneCutoff647=== RUN TestObjectStatsTrigger648=== PAUSE TestObjectStatsTrigger649=== RUN TestObjectStatsUpdatedOncePerCommit650=== PAUSE TestObjectStatsUpdatedOncePerCommit651=== RUN TestOrphanedObjectsGC652=== PAUSE TestOrphanedObjectsGC653=== RUN TestOrphanedObjectsGCStressTest654=== PAUSE TestOrphanedObjectsGCStressTest655=== RUN TestCreatePin_ReservedPins656=== PAUSE TestCreatePin_ReservedPins657=== RUN TestPresentReportsOnlyClosureRoots658=== PAUSE TestPresentReportsOnlyClosureRoots659=== RUN TestPresentRefreshesOnlyStaleClosures660=== PAUSE TestPresentRefreshesOnlyStaleClosures661=== RUN TestPresentNotReportedWhileGCDeletesClosure662=== PAUSE TestPresentNotReportedWhileGCDeletesClosure663=== RUN TestParseSingleRange664=== PAUSE TestParseSingleRange665=== RUN TestProxyHeadersOnlyTrustedOnSocket6662026/11/06 07:44:16 INFO Starting HTTP server address=127.0.0.1:559336672026/11/06 07:44:16 INFO Starting HTTP server address=proxy.sock6682026/11/06 07:44:16 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6692026/11/06 07:44:16 INFO Shutdown signal received, draining in-flight requests timeout=10s670--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.10s)671=== RUN TestIsValidCachePath672=== PAUSE TestIsValidCachePath673=== RUN TestReadProxyNarinfo674=== PAUSE TestReadProxyNarinfo675=== RUN TestReadProxyNarinfoAlreadyDecompressed676=== PAUSE TestReadProxyNarinfoAlreadyDecompressed677=== RUN TestReadProxyContentNegotiation678=== PAUSE TestReadProxyContentNegotiation679=== RUN TestReadProxyNarStreaming680=== PAUSE TestReadProxyNarStreaming681=== RUN TestReadProxy404682=== PAUSE TestReadProxy404683=== RUN TestReadProxyInvalidPath684=== PAUSE TestReadProxyInvalidPath685=== RUN TestReadProxyHead686=== PAUSE TestReadProxyHead687=== RUN TestReadProxyOutlastsServerWriteTimeout688=== PAUSE TestReadProxyOutlastsServerWriteTimeout689=== RUN TestReadProxyConditionalGet690=== PAUSE TestReadProxyConditionalGet691=== RUN TestReadProxyRootRedirectsToIndexHTML692=== PAUSE TestReadProxyRootRedirectsToIndexHTML693=== RUN TestReadProxyDisabled694=== PAUSE TestReadProxyDisabled695=== RUN TestReadRedirectNar696=== PAUSE TestReadRedirectNar697=== RUN TestReadRedirectKeepsNarinfoProxied698=== PAUSE TestReadRedirectKeepsNarinfoProxied699=== RUN TestReadProxyRangeRequest700=== PAUSE TestReadProxyRangeRequest701=== RUN TestReadRedirectUsesPublicS3URL702=== PAUSE TestReadRedirectUsesPublicS3URL703=== RUN TestPush_OverlappingRootsStoreOneRowPerKey704=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey705=== RUN TestPush_CompleteCommitsEveryRoot706=== PAUSE TestPush_CompleteCommitsEveryRoot707=== RUN TestPush_RepeatedRootCommitsOnce708=== PAUSE TestPush_RepeatedRootCommitsOnce709=== RUN TestPush_CompleteWaitsForCleanupOfThePush710=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush711=== RUN TestPush_RootsAreLockedInByteOrder712=== PAUSE TestPush_RootsAreLockedInByteOrder713=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit714=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit715=== RUN TestPush_RejectsBadRequests716=== PAUSE TestPush_RejectsBadRequests717=== RUN TestPush_SignsNarinfosOfItsPendingObjects718=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects719=== RUN TestSharedNarBothUploadsComplete720=== PAUSE TestSharedNarBothUploadsComplete721=== RUN TestCompleteMultipartUpload_ErrorButObjectExists722=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists723=== RUN TestCompletedNarNotReofferedAcrossClosures724=== PAUSE TestCompletedNarNotReofferedAcrossClosures725=== RUN TestPresignedUploadRegisteredBeforeCommit726=== PAUSE TestPresignedUploadRegisteredBeforeCommit727=== RUN TestService_Rustfstest728=== PAUSE TestService_Rustfstest729=== RUN TestParseSize730=== PAUSE TestParseSize731=== RUN TestSkippedUploadsHandler732=== PAUSE TestSkippedUploadsHandler733=== RUN TestSystemdListenerNotActivated734--- PASS: TestSystemdListenerNotActivated (0.00s)735=== RUN TestWatchdogBeatsWhenHealthy736--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)737=== RUN TestWatchdogSkipsWhenUnhealthy7382026/11/06 07:44:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7392026/11/06 07:44:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7402026/11/06 07:44:16 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7412026/11/06 07:44:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7422026/11/06 07:44:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7432026/11/06 07:44:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7442026/11/06 07:44:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7452026/11/06 07:44:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/06 07:44:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/06 07:44:17 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"748--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)749=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle750=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle751=== RUN TestProxyWriteTimeout752=== PAUSE TestProxyWriteTimeout753=== RUN TestPendingClosureWriteTimeout754=== PAUSE TestPendingClosureWriteTimeout755=== RUN TestIsValidUploadKey756=== PAUSE TestIsValidUploadKey757=== RUN TestUploadHandlersRejectInvalidKeys758=== PAUSE TestUploadHandlersRejectInvalidKeys759=== RUN TestUploadHandlersRejectOversizedBody760=== PAUSE TestUploadHandlersRejectOversizedBody761=== RUN TestService_cleanupPendingClosuresHandler762=== PAUSE TestService_cleanupPendingClosuresHandler763=== RUN TestService_createPendingClosureHandler764=== PAUSE TestService_createPendingClosureHandler765=== RUN TestService_verifyS3Integrity766=== PAUSE TestService_verifyS3Integrity767=== RUN TestService_verifyS3ReuploadsStaleNarinfo768=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo769=== RUN TestCompleteMultipartUnregistered770=== PAUSE TestCompleteMultipartUnregistered771=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT772=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT773=== CONT TestAbortSucceeded774=== CONT TestPresentReportsOnlyClosureRoots775=== CONT TestOrphanedObjectsGC776=== CONT TestCompletedNarNotReofferedAcrossClosures777=== CONT TestForceGCDuringPushOffersSweptObject778=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows779=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows780=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check781=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check782=== CONT TestGracefulShutdownDrainsInflight783--- PASS: TestAbortSucceeded (0.00s)784=== CONT TestCreatePin_ReservedPins785=== CONT TestProxyWriteTimeout786=== CONT TestOrphanedObjectsGCStressTest787=== CONT TestPush_RootsAreLockedInByteOrder788=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT7892026/11/06 07:44:17 INFO Starting HTTP server address=127.0.0.1:55935790=== CONT TestCompleteMultipartUnregistered791=== CONT TestService_verifyS3ReuploadsStaleNarinfo792=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed793=== CONT TestService_verifyS3Integrity794=== CONT TestService_createPendingClosureHandler795=== CONT TestService_cleanupPendingClosuresHandler796=== CONT TestUploadHandlersRejectOversizedBody797=== CONT TestUploadHandlersRejectInvalidKeys798=== CONT TestIsValidUploadKey799=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info800=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info801=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal802=== CONT TestPendingClosureWriteTimeout803=== RUN TestPendingClosureWriteTimeout/empty804=== CONT TestCompleteMultipartUpload_ErrorButObjectExists805=== PAUSE TestPendingClosureWriteTimeout/empty806=== RUN TestPendingClosureWriteTimeout/400_objects807=== PAUSE TestPendingClosureWriteTimeout/400_objects808=== RUN TestPendingClosureWriteTimeout/670k_objects809=== PAUSE TestPendingClosureWriteTimeout/670k_objects810=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline811=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline812=== CONT TestObjectStatsTrigger813=== CONT TestSharedNarBothUploadsComplete814=== CONT TestPush_SignsNarinfosOfItsPendingObjects815=== CONT TestPush_RejectsBadRequests816=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit817=== CONT TestObjectStatsUpdatedOncePerCommit818=== RUN TestProxyWriteTimeout/narinfo8192026/11/06 07:44:17 INFO Shutdown signal received, draining in-flight requests timeout=10s820=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed821=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal822=== RUN TestIsValidUploadKey/narinfo823=== PAUSE TestProxyWriteTimeout/narinfo824=== RUN TestProxyWriteTimeout/1_GiB_nar825=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key826=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key827=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key828=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key829=== CONT TestPendingCleanupUsesOneCutoff830=== PAUSE TestIsValidUploadKey/narinfo831=== RUN TestIsValidUploadKey/nar_zst832=== PAUSE TestIsValidUploadKey/nar_zst833=== RUN TestIsValidUploadKey/nar_xz834=== PAUSE TestIsValidUploadKey/nar_xz835=== RUN TestIsValidUploadKey/nar_plain836=== PAUSE TestIsValidUploadKey/nar_plain837=== RUN TestIsValidUploadKey/listing838=== PAUSE TestIsValidUploadKey/listing839=== RUN TestIsValidUploadKey/build_log840=== PAUSE TestIsValidUploadKey/build_log841=== RUN TestIsValidUploadKey/build_log_home-manager_file842=== PAUSE TestIsValidUploadKey/build_log_home-manager_file843=== RUN TestIsValidUploadKey/build_log_plus_in_name844=== PAUSE TestIsValidUploadKey/build_log_plus_in_name845=== RUN TestIsValidUploadKey/build_log_question_mark846=== PAUSE TestIsValidUploadKey/build_log_question_mark847=== RUN TestIsValidUploadKey/build_log_equals848=== PAUSE TestIsValidUploadKey/build_log_equals849=== RUN TestIsValidUploadKey/realisation850=== PAUSE TestIsValidUploadKey/realisation851=== RUN TestIsValidUploadKey/realisation_plus_in_output852=== PAUSE TestIsValidUploadKey/realisation_plus_in_output853=== RUN TestIsValidUploadKey/nix-cache-info854=== PAUSE TestIsValidUploadKey/nix-cache-info855=== RUN TestIsValidUploadKey/index.html856=== PAUSE TestIsValidUploadKey/index.html857=== RUN TestIsValidUploadKey/narinfo_key,_nar_type858=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type859=== RUN TestIsValidUploadKey/nar_key,_narinfo_type860=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type861=== RUN TestIsValidUploadKey/listing_key,_narinfo_type862=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type863=== RUN TestIsValidUploadKey/traversal864=== PAUSE TestIsValidUploadKey/traversal865=== RUN TestIsValidUploadKey/traversal_nar866=== PAUSE TestIsValidUploadKey/traversal_nar867=== RUN TestIsValidUploadKey/absolute868=== PAUSE TestIsValidUploadKey/absolute869=== RUN TestIsValidUploadKey/empty_key870=== PAUSE TestIsValidUploadKey/empty_key871=== RUN TestIsValidUploadKey/unknown_type872=== PAUSE TestIsValidUploadKey/unknown_type873=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded874--- PASS: TestGracefulShutdownDrainsInflight (0.07s)875=== CONT TestMultipartCleanup876=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed877=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed878=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost879=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost880=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed881=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed882=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed883=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed884=== CONT TestServerTLSConfig885=== RUN TestServerTLSConfig/no_client_CA886=== PAUSE TestServerTLSConfig/no_client_CA887=== RUN TestServerTLSConfig/missing_CA_file888=== PAUSE TestServerTLSConfig/missing_CA_file889=== RUN TestServerTLSConfig/not_a_PEM_file890=== PAUSE TestServerTLSConfig/not_a_PEM_file891=== CONT TestService_NativeMTLS892=== PAUSE TestProxyWriteTimeout/1_GiB_nar893=== RUN TestProxyWriteTimeout/10_GiB_nar894=== PAUSE TestProxyWriteTimeout/10_GiB_nar895=== RUN TestProxyWriteTimeout/unknown_size896=== PAUSE TestProxyWriteTimeout/unknown_size897=== CONT TestMetricsCommit898=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure899=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure900=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart901=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart902=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts903=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts904=== CONT TestMetricsInventory9052026/11/06 07:44:17 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55937/oidc906--- PASS: TestPresentReportsOnlyClosureRoots (0.86s)907=== CONT TestNARDeduplicationMetadataUploadBug9082026/11/06 07:44:18 INFO Received uploads request method=POST path=/api/pending_closures9092026/11/06 07:44:18 INFO Received uploads request method=POST path=/api/pending_closures910--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.70s)911=== CONT TestCreatePendingClosureRejectsOversizedNAR9122026/11/06 07:44:18 INFO Received uploads request method=POST path=/api/pending_closures913--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)914=== CONT TestCacheConfigHandlerMaxNarSize915--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)916=== CONT TestEnsureAbortUploadsRule9172026/11/06 07:44:19 INFO Received cleanup request method=DELETE path=/api/pending_closures9182026/11/06 07:44:19 INFO Aborted multipart uploads count=0 kept=09192026/11/06 07:44:19 INFO Received uploads request method=POST path=/api/pending_closures9202026/11/06 07:44:19 INFO Received cleanup request method=DELETE path=/api/pending_closures9212026/11/06 07:44:19 INFO Aborted multipart uploads count=1 kept=09222026/11/06 07:44:19 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9232026-11-06 07:44:19.221 UTC [94762] ERROR: Closure does not exist: id=19242026-11-06 07:44:19.221 UTC [94762] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9252026-11-06 07:44:19.221 UTC [94762] STATEMENT: -- name: CommitPendingClosure :one926 SELECT commit_pending_closure($1::bigint)::bigint927 928--- PASS: TestService_cleanupPendingClosuresHandler (2.09s)929=== CONT TestGenerateLandingPage930--- PASS: TestGenerateLandingPage (0.00s)931=== CONT TestService_readinessHandler9322026/11/06 07:44:19 INFO Received uploads request method=POST path=/api/pending_closures9332026/11/06 07:44:19 INFO Received push request method=POST path=/api/pushes9342026-11-06 07:44:20.017 UTC [94763] ERROR: could not obtain lock on row in relation "closures"9352026-11-06 07:44:20.017 UTC [94763] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9362026-11-06 07:44:20.018 UTC [94763] ERROR: could not obtain lock on row in relation "closures"9372026-11-06 07:44:20.018 UTC [94763] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9382026-11-06 07:44:20.030 UTC [94763] ERROR: could not obtain lock on row in relation "closures"9392026-11-06 07:44:20.030 UTC [94763] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9402026-11-06 07:44:20.039 UTC [94763] ERROR: could not obtain lock on row in relation "closures"9412026-11-06 07:44:20.039 UTC [94763] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9422026-11-06 07:44:20.061 UTC [94763] ERROR: could not obtain lock on row in relation "closures"9432026-11-06 07:44:20.061 UTC [94763] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT944--- PASS: TestPush_RootsAreLockedInByteOrder (2.96s)945=== CONT TestService_healthCheckHandler9462026/11/06 07:44:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9472026/11/06 07:44:20 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst948--- PASS: TestCompleteMultipartUnregistered (3.18s)949=== CONT TestReadProxyOutlastsServerWriteTimeout950=== NAME TestOrphanedObjectsGC951 orphaned_objects_gc_test.go:287: GC Test Summary:952 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A953 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B954 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)955 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)956 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects957--- PASS: TestOrphanedObjectsGC (3.23s)958=== CONT TestPush_CompleteWaitsForCleanupOfThePush9592026/11/06 07:44:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9602026/11/06 07:44:20 INFO Received uploads request method=POST path=/api/pending_closures9612026/11/06 07:44:20 INFO Received uploads request method=POST path=/api/pending_closures9622026/11/06 07:44:20 INFO Received uploads request method=POST path=/api/pending_closures9632026/11/06 07:44:20 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LjFmYzRmZjM2LTg4ZGYtNGUwNS04YzFiLWFjMDVlZTQ5MzcyOHgxNzkzOTUxMDU4NDU4NjY3MDAw parts=129642026/11/06 07:44:20 INFO Received uploads request method=POST path=/api/pending_closures965--- PASS: TestCompletedNarNotReofferedAcrossClosures (3.57s)966=== CONT TestPush_RepeatedRootCommitsOnce9672026/11/06 07:44:20 INFO Received uploads request method=POST path=/api/pending_closures9682026/11/06 07:44:21 INFO Received cleanup request method=DELETE path=/api/pending_closures9692026/11/06 07:44:21 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket14/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""9702026/11/06 07:44:21 INFO Aborted multipart uploads count=0 kept=19712026/11/06 07:44:21 INFO Received cleanup request method=DELETE path=/api/pending_closures9722026/11/06 07:44:21 INFO Aborted multipart uploads count=1 kept=09732026/11/06 07:44:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete974--- PASS: TestMultipartCleanup (3.89s)975=== CONT TestPush_CompleteCommitsEveryRoot9762026/11/06 07:44:21 INFO Received uploads request method=POST path=/api/pending_closures9772026/11/06 07:44:21 INFO Received uploads request method=POST path=/api/pending_closures9782026/11/06 07:44:21 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LjJhZDkzMGE5LWJkZjYtNGY4OS1iMTlmLWY0ZWNmMDdlMTc0MXgxNzkzOTUxMDU5NDcyMTY0MDAw parts=109792026/11/06 07:44:21 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9802026/11/06 07:44:21 INFO Completed upload id=1 objects=2 duration=25.853916ms9812026/11/06 07:44:21 INFO Received uploads request method=POST path=/api/pending_closures9822026/11/06 07:44:21 INFO Received uploads request method=POST path=/api/pending_closures9832026/11/06 07:44:21 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9842026/11/06 07:44:21 WARN Found objects in DB but missing from S3, will re-upload count=1985--- PASS: TestService_verifyS3Integrity (4.11s)986=== CONT TestPush_OverlappingRootsStoreOneRowPerKey9872026/11/06 07:44:21 INFO Received uploads request method=POST path=/api/pending_closures988--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (4.33s)989=== CONT TestReadRedirectUsesPublicS3URL9902026/11/06 07:44:21 INFO Received uploads request method=POST path=/api/pending_closures9912026/11/06 07:44:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9922026/11/06 07:44:22 INFO Received push request method=POST path=/api/pushes9932026/11/06 07:44:22 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LmZiZjYyMjIwLTg1MWYtNDY2Zi1iOTcwLTUxZGRmMjBlMTA0N3gxNzkzOTUxMDYwNjQzOTU5MDAw parts=109942026/11/06 07:44:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9952026/11/06 07:44:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9962026/11/06 07:44:22 INFO Completed upload id=1 objects=2 duration=14.855ms9972026/11/06 07:44:22 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009982026/11/06 07:44:22 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LmFhYmFhODhhLTY3YWMtNDc2My04ZTQ4LTRmZmM0ZmI1ZjlkMXgxNzkzOTUxMDYxNzUwNDQwMDAw9992026/11/06 07:44:22 INFO Received uploads request method=POST path=/api/pending_closures10002026/11/06 07:44:22 INFO Starting cleanup of old closures method=DELETE path=/api/closures10012026/11/06 07:44:22 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LmFhYmFhODhhLTY3YWMtNDc2My04ZTQ4LTRmZmM0ZmI1ZjlkMXgxNzkzOTUxMDYxNzUwNDQwMDAw parts=11002--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (4.95s)10032026/11/06 07:44:22 INFO Aborted multipart uploads count=0 kept=01004=== CONT TestReadProxyRangeRequest10052026/11/06 07:44:22 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010062026/11/06 07:44:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10072026/11/06 07:44:22 INFO Signed narinfos id=1 count=110082026/11/06 07:44:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10092026/11/06 07:44:22 INFO Vacuumed table table=pending_closures10102026/11/06 07:44:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10112026/11/06 07:44:22 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10122026/11/06 07:44:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10132026/11/06 07:44:22 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10142026/11/06 07:44:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10152026/11/06 07:44:22 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110162026/11/06 07:44:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10172026/11/06 07:44:22 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1018--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (5.00s)1019=== CONT TestReadRedirectKeepsNarinfoProxied10202026/11/06 07:44:22 INFO Vacuumed table table=pending_objects10212026/11/06 07:44:22 INFO Vacuumed table table=multipart_uploads10222026/11/06 07:44:22 INFO Vacuumed table table=closures10232026/11/06 07:44:22 INFO Vacuumed table table=objects10242026/11/06 07:44:22 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001025--- PASS: TestService_createPendingClosureHandler (5.14s)1026=== CONT TestReadRedirectNar10272026/11/06 07:44:22 INFO Received push request method=POST path=/api/pushes10282026/11/06 07:44:22 INFO Received complete push request method=POST path=/api/pushes/1/complete10292026/11/06 07:44:22 INFO Completed push id=1 objects=4 duration=46.108084ms10302026/11/06 07:44:22 INFO Received push request method=POST path=/api/pushes10312026/11/06 07:44:22 INFO Aborted multipart uploads count=0 kept=010322026/11/06 07:44:22 WARN Force mode enabled - objects will be deleted immediately without grace period10332026/11/06 07:44:22 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=010342026/11/06 07:44:22 INFO Vacuumed table table=pending_closures10352026/11/06 07:44:22 INFO Vacuumed table table=pending_objects10362026/11/06 07:44:22 INFO Vacuumed table table=multipart_uploads10372026/11/06 07:44:22 INFO Vacuumed table table=closures10382026/11/06 07:44:22 INFO Vacuumed table table=objects10392026/11/06 07:44:22 INFO Received complete push request method=POST path=/api/pushes/2/complete10402026/11/06 07:44:22 INFO Completed push id=2 objects=4 duration=9.8705ms1041--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (5.55s)1042=== CONT TestReadProxyDisabled10432026/11/06 07:44:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1044--- PASS: TestObjectStatsUpdatedOncePerCommit (5.65s)1045=== CONT TestReadProxyRootRedirectsToIndexHTML10462026/11/06 07:44:22 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LmY3Y2M1YjUyLWY4YzMtNDZmMS1iNTljLWFjMDVhOGI5YzY5NngxNzkzOTUxMDYxMTQ1Nzc5MDAw parts=121047--- PASS: TestObjectStatsTrigger (5.75s)1048=== CONT TestReadProxyConditionalGet1049=== RUN TestPush_RejectsBadRequests/no_objects1050=== PAUSE TestPush_RejectsBadRequests/no_objects1051=== RUN TestPush_RejectsBadRequests/bad_root1052=== PAUSE TestPush_RejectsBadRequests/bad_root1053=== RUN TestPush_RejectsBadRequests/root_not_in_objects1054=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1055=== RUN TestPush_RejectsBadRequests/no_roots1056=== PAUSE TestPush_RejectsBadRequests/no_roots1057=== CONT TestGCEndsOnShutdown1058=== RUN TestGCEndsOnShutdown/before_the_run1059=== PAUSE TestGCEndsOnShutdown/before_the_run1060=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1061=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1062=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1063=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1064=== CONT TestGCTaskStore_Fail1065--- PASS: TestGCTaskStore_Fail (0.00s)1066=== CONT TestGCTaskStore_PhaseUpdates1067--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1068=== CONT TestGCTaskStore_CompletedAllowsNewTask1069--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1070=== CONT TestGCTaskStore_GetReturnsLatest1071--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1072=== CONT TestGCTaskStore_GetEmpty1073--- PASS: TestGCTaskStore_GetEmpty (0.00s)1074=== CONT TestGCTaskStore_ConflictDifferentParams1075--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1076=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1077--- PASS: TestMetricsInventory (6.33s)1078=== CONT TestCommitRacingPendingCleanupKeepsObjects10792026/11/06 07:44:23 WARN mTLS auth: subject not in bound subjects subject="CN=reader"10802026/11/06 07:44:23 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1081--- PASS: TestService_NativeMTLS (6.46s)1082=== CONT TestGCTaskStore_DeduplicateSameParams1083--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1084=== CONT TestGCTaskStore_StartNew1085--- PASS: TestGCTaskStore_StartNew (0.00s)1086=== CONT TestReadProxyNarinfoAlreadyDecompressed10872026/11/06 07:44:23 INFO Received uploads request method=POST path=/api/pending_closures10882026/11/06 07:44:24 INFO Received uploads request method=POST path=/api/pending_closures10892026/11/06 07:44:24 INFO Received cleanup request method=DELETE path=/api/pending_closures10902026/11/06 07:44:24 INFO Received push request method=POST path=/api/pushes10912026/11/06 07:44:24 INFO Received complete push request method=POST path=/api/pushes/1/complete10922026/11/06 07:44:24 INFO Completed push id=1 objects=4 duration=29.984042ms10932026/11/06 07:44:24 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete10942026/11/06 07:44:24 INFO Completed upload id=2 objects=2 duration=569µs1095--- PASS: TestMetricsCommit (7.18s)1096=== CONT TestReadProxyHead10972026/11/06 07:44:24 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10982026/11/06 07:44:24 WARN Refused reserved pin name=worker-x86_64-linux10992026/11/06 07:44:24 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11002026/11/06 07:44:24 INFO Received create pin request method=POST path=/api/pins/my-app11012026/11/06 07:44:24 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11022026/11/06 07:44:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1103--- PASS: TestCreatePin_ReservedPins (7.43s)1104=== CONT TestReadProxyInvalidPath11052026/11/06 07:44:24 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LjAzYjNlZDllLThiOGUtNDJjMi05NTk2LTdlNjVmODM2MGMwN3gxNzkzOTUxMDYxMTk0MjQyMDAw parts=121106--- PASS: TestSharedNarBothUploadsComplete (7.49s)1107=== CONT TestReadProxy4041108=== NAME TestNARDeduplicationMetadataUploadBug1109 metadata_upload_test.go:48: First store path: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestNARDeduplicationMetadataUploadBug2838353166/001/store/ds2nnrifjx4nz5cwspd9vzqrj7vgp012-file1.txt11102026/11/06 07:44:25 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket29 days=21111--- PASS: TestEnsureAbortUploadsRule (6.30s)1112=== CONT TestPushWaitsForSweepHoldingRow11132026/11/06 07:44:25 INFO Received push request method=POST path=/api/pushes11142026/11/06 07:44:25 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11152026/11/06 07:44:25 INFO Uploading ds2nnrifjx4nz5cwspd9vzqrj7vgp012-file1.txt (160B)11162026/11/06 07:44:25 WARN readiness check failed error="closed pool"1117--- PASS: TestService_readinessHandler (6.05s)1118=== CONT TestReadProxyNarStreaming11192026/11/06 07:44:25 WARN Failed to register uploaded object key=ds2nnrifjx4nz5cwspd9vzqrj7vgp012.ls error="server returned 404: 404 page not found\n"11202026/11/06 07:44:25 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11212026/11/06 07:44:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11222026/11/06 07:44:25 INFO Signed narinfos id=1 count=111232026/11/06 07:44:25 INFO Uploading 1 narinfos11242026/11/06 07:44:25 INFO Received complete push request method=POST path=/api/pushes/1/complete11252026/11/06 07:44:25 WARN Failed to register uploaded object key=ds2nnrifjx4nz5cwspd9vzqrj7vgp012.narinfo error="server returned 404: 404 page not found\n"11262026/11/06 07:44:25 INFO Completed push id=1 objects=3 duration=19.669291ms11272026/11/06 07:44:25 INFO Upload complete. (224ms)1128=== NAME TestNARDeduplicationMetadataUploadBug1129 metadata_upload_test.go:54: Retrieved narinfo from S3:1130 StorePath: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestNARDeduplicationMetadataUploadBug2838353166/001/store/ds2nnrifjx4nz5cwspd9vzqrj7vgp012-file1.txt1131 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1132 Compression: zstd1133 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1134 NarSize: 1601135 References: 1136 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1137 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1138 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1139 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1140 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestNARDeduplicationMetadataUploadBug2838353166/001/store/dj1yws4c2rf8lkpr6m5vni41xnss6hy5-file2.txt1141--- PASS: TestService_healthCheckHandler (5.41s)1142=== CONT TestSweepRechecksPendingAfterLocking11432026/11/06 07:44:25 INFO Received push request method=POST path=/api/pushes11442026/11/06 07:44:25 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11452026/11/06 07:44:25 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11462026/11/06 07:44:25 WARN Failed to register uploaded object key=dj1yws4c2rf8lkpr6m5vni41xnss6hy5.ls error="server returned 404: 404 page not found\n"11472026/11/06 07:44:25 INFO Signed narinfos id=2 count=111482026/11/06 07:44:25 INFO Uploading 1 narinfos11492026/11/06 07:44:25 INFO Received complete push request method=POST path=/api/pushes/2/complete11502026/11/06 07:44:25 WARN Failed to register uploaded object key=dj1yws4c2rf8lkpr6m5vni41xnss6hy5.narinfo error="server returned 404: 404 page not found\n"11512026/11/06 07:44:25 INFO Completed push id=2 objects=3 duration=1.155875ms11522026/11/06 07:44:25 INFO Upload complete. (134ms)1153=== NAME TestNARDeduplicationMetadataUploadBug1154 metadata_upload_test.go:76: Retrieved narinfo from S3:1155 StorePath: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestNARDeduplicationMetadataUploadBug2838353166/001/store/dj1yws4c2rf8lkpr6m5vni41xnss6hy5-file2.txt1156 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1157 Compression: zstd1158 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1159 NarSize: 1601160 References: 1161 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1162 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1163 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1164 {"version":1,"root":{"type":"regular","size":44}}1165--- PASS: TestNARDeduplicationMetadataUploadBug (7.73s)1166=== CONT TestReadProxyContentNegotiation11672026/11/06 07:44:25 INFO Received push request method=POST path=/api/pushes11682026-11-06 07:44:26.144 UTC [94866] ERROR: Push does not exist: id=111692026-11-06 07:44:26.144 UTC [94866] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11702026-11-06 07:44:26.144 UTC [94866] STATEMENT: SELECT commit_push($1)1171--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (5.78s)1172=== CONT TestGetExistingObjectsLocksRows11732026/11/06 07:44:26 INFO Received push request method=POST path=/api/pushes11742026/11/06 07:44:26 INFO Received complete push request method=POST path=/api/pushes/1/complete11752026/11/06 07:44:26 INFO Completed push id=1 objects=4 duration=34.380458ms1176--- PASS: TestPush_RepeatedRootCommitsOnce (5.62s)1177=== CONT TestRegisterCompletedObjectNeedsPendingRow11782026/11/06 07:44:26 INFO Received push request method=POST path=/api/pushes11792026/11/06 07:44:26 INFO Received complete push request method=POST path=/api/pushes/1/complete11802026/11/06 07:44:26 INFO Completed push id=1 objects=6 duration=35.456125ms1181--- PASS: TestPush_CompleteCommitsEveryRoot (5.48s)1182=== CONT TestParseSize1183--- PASS: TestParseSize (0.00s)1184=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle11852026/11/06 07:44:26 INFO Received push request method=POST path=/api/pushes1186--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (5.50s)1187=== CONT TestSkippedUploadsHandler11882026/11/06 07:44:26 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001189--- PASS: TestSkippedUploadsHandler (0.00s)1190=== CONT TestSweepSkipsRowsLockedByPush1191--- PASS: TestReadRedirectUsesPublicS3URL (5.41s)1192=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1193--- PASS: TestReadRedirectKeepsNarinfoProxied (5.06s)1194=== CONT TestFailedS3DeleteKeepsTombstone1195--- PASS: TestReadRedirectNar (5.10s)1196=== CONT TestParseSingleRange1197=== RUN TestParseSingleRange/none1198=== PAUSE TestParseSingleRange/none1199=== RUN TestParseSingleRange/unknown_unit1200=== PAUSE TestParseSingleRange/unknown_unit1201=== RUN TestParseSingleRange/multi-range_ignored1202=== PAUSE TestParseSingleRange/multi-range_ignored1203=== RUN TestParseSingleRange/malformed_no_dash1204=== PAUSE TestParseSingleRange/malformed_no_dash1205=== RUN TestParseSingleRange/malformed_both_empty1206=== PAUSE TestParseSingleRange/malformed_both_empty1207=== RUN TestParseSingleRange/malformed_end_before_start1208=== PAUSE TestParseSingleRange/malformed_end_before_start1209=== RUN TestParseSingleRange/closed1210=== PAUSE TestParseSingleRange/closed1211=== RUN TestParseSingleRange/open-ended1212=== PAUSE TestParseSingleRange/open-ended1213=== RUN TestParseSingleRange/end_clamped_to_size1214=== PAUSE TestParseSingleRange/end_clamped_to_size1215=== RUN TestParseSingleRange/suffix1216=== PAUSE TestParseSingleRange/suffix1217=== RUN TestParseSingleRange/suffix_exceeds_size1218=== PAUSE TestParseSingleRange/suffix_exceeds_size1219=== RUN TestParseSingleRange/single_byte1220=== PAUSE TestParseSingleRange/single_byte1221=== RUN TestParseSingleRange/start_past_EOF1222=== PAUSE TestParseSingleRange/start_past_EOF1223=== RUN TestParseSingleRange/start_far_past_EOF1224=== PAUSE TestParseSingleRange/start_far_past_EOF1225=== CONT TestReadProxyNarinfo1226--- PASS: TestReadProxyRangeRequest (5.53s)1227=== CONT TestIsValidCachePath1228=== RUN TestIsValidCachePath/narinfo1229=== PAUSE TestIsValidCachePath/narinfo1230=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1231=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1232=== RUN TestIsValidCachePath/nar_zst1233=== PAUSE TestIsValidCachePath/nar_zst1234=== RUN TestIsValidCachePath/nar_xz1235=== PAUSE TestIsValidCachePath/nar_xz1236=== RUN TestIsValidCachePath/nar_bz21237=== PAUSE TestIsValidCachePath/nar_bz21238=== RUN TestIsValidCachePath/nar_uncompressed1239=== PAUSE TestIsValidCachePath/nar_uncompressed1240=== RUN TestIsValidCachePath/ls1241=== PAUSE TestIsValidCachePath/ls1242=== RUN TestIsValidCachePath/log1243=== PAUSE TestIsValidCachePath/log1244=== RUN TestIsValidCachePath/realisation1245=== PAUSE TestIsValidCachePath/realisation1246=== RUN TestIsValidCachePath/nix-cache-info1247=== PAUSE TestIsValidCachePath/nix-cache-info1248=== RUN TestIsValidCachePath/index.html1249=== PAUSE TestIsValidCachePath/index.html1250=== RUN TestIsValidCachePath/traversal_parent1251=== PAUSE TestIsValidCachePath/traversal_parent1252=== RUN TestIsValidCachePath/traversal_in_middle1253=== PAUSE TestIsValidCachePath/traversal_in_middle1254=== RUN TestIsValidCachePath/invalid_char_e1255=== PAUSE TestIsValidCachePath/invalid_char_e1256=== RUN TestIsValidCachePath/invalid_char_u1257=== PAUSE TestIsValidCachePath/invalid_char_u1258=== RUN TestIsValidCachePath/random_path1259=== PAUSE TestIsValidCachePath/random_path1260=== RUN TestIsValidCachePath/empty1261=== PAUSE TestIsValidCachePath/empty1262=== RUN TestIsValidCachePath/leading_slash1263=== PAUSE TestIsValidCachePath/leading_slash1264=== RUN TestIsValidCachePath/wrong_extension1265=== PAUSE TestIsValidCachePath/wrong_extension1266=== RUN TestIsValidCachePath/short_hash1267=== PAUSE TestIsValidCachePath/short_hash1268=== CONT TestPresentNotReportedWhileGCDeletesClosure1269=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1270=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1271=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1272=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1273=== CONT TestService_Rustfstest1274--- PASS: TestReadProxyDisabled (5.11s)1275=== CONT TestPresignedUploadRegisteredBeforeCommit1276--- PASS: TestReadProxyRootRedirectsToIndexHTML (5.22s)1277=== CONT TestPresentRefreshesOnlyStaleClosures1278--- PASS: TestReadProxyConditionalGet (5.38s)1279=== CONT TestClientFallsBackToClosures1280=== NAME TestOrphanedObjectsGCStressTest1281 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains12822026/11/06 07:44:28 INFO Received uploads request method=POST path=/api/pending_closures12832026/11/06 07:44:28 INFO Aborted multipart uploads count=0 kept=012842026/11/06 07:44:28 WARN Force mode enabled - objects will be deleted immediately without grace period1285 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion12862026/11/06 07:44:28 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=012872026/11/06 07:44:28 INFO Vacuumed table table=pending_closures12882026/11/06 07:44:28 INFO Vacuumed table table=pending_objects12892026/11/06 07:44:28 INFO Vacuumed table table=multipart_uploads12902026/11/06 07:44:28 INFO Vacuumed table table=closures12912026/11/06 07:44:28 INFO Vacuumed table table=objects12922026/11/06 07:44:28 INFO Aborted multipart uploads count=0 kept=012932026/11/06 07:44:28 WARN Force mode enabled - objects will be deleted immediately without grace period12942026/11/06 07:44:28 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=012952026/11/06 07:44:28 INFO Vacuumed table table=pending_closures1296=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12972026/11/06 07:44:28 INFO Vacuumed table table=pending_objects12982026/11/06 07:44:28 INFO Vacuumed table table=multipart_uploads12992026/11/06 07:44:28 INFO Vacuumed table table=closures13002026/11/06 07:44:28 INFO Vacuumed table table=objects1301--- PASS: TestCommitRacingPendingCleanupKeepsObjects (5.35s)1302=== CONT TestGCSweepDeliversEachKeyOnce1303--- PASS: TestReadProxyNarinfoAlreadyDecompressed (5.29s)1304=== CONT TestTombstonedObjectOfferedWithoutWaiting1305--- PASS: TestReadProxyHead (4.77s)1306=== CONT TestGCSweepSkipsPendingObjects1307--- PASS: TestReadProxyInvalidPath (4.76s)1308=== CONT TestDeduplicatedObjectsRecordedAsPending13092026/11/06 07:44:29 INFO Received uploads request method=POST path=/api/pending_closures1310--- PASS: TestReadProxy404 (5.50s)1311=== CONT TestPushDedupSurvivesConcurrentGC13122026/11/06 07:44:30 INFO Aborted multipart uploads count=1 kept=01313--- PASS: TestReadProxyNarStreaming (4.93s)1314=== CONT TestGCMetrics13152026/11/06 07:44:30 INFO Received cleanup request method=DELETE path=/api/pending_closures1316--- PASS: TestReadProxyOutlastsServerWriteTimeout (9.93s)1317=== CONT TestGCBugBareHashReferences13182026/11/06 07:44:30 INFO Aborted multipart uploads count=1 kept=01319--- PASS: TestPendingCleanupUsesOneCutoff (13.06s)1320=== CONT TestGCAdvisoryLockBlocksConcurrentRun1321--- PASS: TestPushWaitsForSweepHoldingRow (5.28s)1322=== CONT TestLeadEndsOnShutdown13232026/11/06 07:44:30 INFO Aborted multipart uploads count=0 kept=013242026/11/06 07:44:30 WARN Force mode enabled - objects will be deleted immediately without grace period13252026/11/06 07:44:30 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013262026/11/06 07:44:30 INFO Vacuumed table table=pending_closures13272026/11/06 07:44:30 INFO Vacuumed table table=pending_objects13282026/11/06 07:44:30 INFO Vacuumed table table=multipart_uploads13292026/11/06 07:44:30 INFO Vacuumed table table=closures13302026/11/06 07:44:30 INFO Vacuumed table table=objects1331--- PASS: TestSweepRechecksPendingAfterLocking (5.09s)1332=== CONT TestLeadIncumbentAnnouncesAtOnce1333--- PASS: TestReadProxyContentNegotiation (5.01s)1334=== CONT TestLeadElectsOneAndHandsOver1335--- PASS: TestGetExistingObjectsLocksRows (4.78s)1336=== CONT TestConnectWaitsForAPeerMigration1337--- PASS: TestRegisterCompletedObjectNeedsPendingRow (4.84s)1338=== CONT TestResolveDBConnectionString1339=== RUN TestResolveDBConnectionString/flag_wins1340=== PAUSE TestResolveDBConnectionString/flag_wins1341=== RUN TestResolveDBConnectionString/file_when_flag_empty1342=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1343=== RUN TestResolveDBConnectionString/missing_file_is_an_error1344=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1345=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1346=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1347=== RUN TestResolveDBConnectionString/nothing_configured1348=== PAUSE TestResolveDBConnectionString/nothing_configured1349=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock13502026/11/06 07:44:31 INFO Received uploads request method=POST path=/api/pending_closures13512026/11/06 07:44:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13522026/11/06 07:44:31 INFO Aborted multipart uploads count=0 kept=013532026/11/06 07:44:31 WARN Force mode enabled - objects will be deleted immediately without grace period13542026/11/06 07:44:31 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=013552026/11/06 07:44:31 INFO Vacuumed table table=pending_closures13562026/11/06 07:44:31 INFO Vacuumed table table=pending_objects13572026/11/06 07:44:31 INFO Vacuumed table table=multipart_uploads13582026/11/06 07:44:31 INFO Vacuumed table table=closures13592026/11/06 07:44:31 INFO Vacuumed table table=objects13602026/11/06 07:44:31 INFO Aborted multipart uploads count=0 kept=013612026/11/06 07:44:31 WARN Force mode enabled - objects will be deleted immediately without grace period13622026/11/06 07:44:32 INFO Received uploads request method=POST path=/api/pending_closures13632026/11/06 07:44:32 INFO Aborted multipart uploads count=0 kept=013642026/11/06 07:44:32 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=013652026/11/06 07:44:32 INFO Vacuumed table table=pending_closures13662026/11/06 07:44:32 INFO Vacuumed table table=pending_objects13672026/11/06 07:44:32 INFO Vacuumed table table=multipart_uploads13682026/11/06 07:44:32 INFO Vacuumed table table=closures13692026/11/06 07:44:32 WARN Force mode enabled - objects will be deleted immediately without grace period13702026/11/06 07:44:32 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013712026/11/06 07:44:32 INFO Vacuumed table table=objects1372--- PASS: TestSweepSkipsRowsLockedByPush (5.45s)1373=== CONT TestDeleteClosuresRacingPins13742026/11/06 07:44:32 INFO Vacuumed table table=pending_closures13752026/11/06 07:44:32 INFO Vacuumed table table=pending_objects13762026/11/06 07:44:32 INFO Vacuumed table table=multipart_uploads13772026/11/06 07:44:32 INFO Vacuumed table table=closures13782026/11/06 07:44:32 INFO Vacuumed table table=objects13792026/11/06 07:44:32 INFO Received uploads request method=POST path=/api/pending_closures1380=== CONT TestCacheStatsHandler1381--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)1382 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (5.87s)1383 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (5.41s)13842026/11/06 07:44:32 INFO Aborted multipart uploads count=0 kept=013852026/11/06 07:44:32 WARN Force mode enabled - objects will be deleted immediately without grace period13862026/11/06 07:44:32 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."13872026/11/06 07:44:32 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1388--- PASS: TestFailedS3DeleteKeepsTombstone (5.41s)1389=== CONT TestClientPushesUseOnePush13902026/11/06 07:44:32 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1391--- PASS: TestReadProxyNarinfo (5.34s)1392=== CONT TestPinProtectsFromGC1393--- PASS: TestService_Rustfstest (5.28s)1394=== CONT TestClientSharedPathCommittedMidPush13952026/11/06 07:44:33 INFO Received uploads request method=POST path=/api/pending_closures13962026/11/06 07:44:33 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst13972026/11/06 07:44:33 INFO Received uploads request method=POST path=/api/pending_closures1398--- PASS: TestPresignedUploadRegisteredBeforeCommit (5.50s)1399=== CONT TestClientWithDependencies1400--- PASS: TestPresentRefreshesOnlyStaleClosures (5.41s)1401=== CONT TestClientMultipleUploads14022026/11/06 07:44:34 INFO Aborted multipart uploads count=0 kept=014032026/11/06 07:44:34 WARN Force mode enabled - objects will be deleted immediately without grace period14042026/11/06 07:44:34 INFO Received uploads request method=POST path=/api/pending_closures14052026/11/06 07:44:34 INFO Received uploads request method=POST path=/api/pending_closures14062026/11/06 07:44:34 INFO Received uploads request method=POST path=/api/pending_closures14072026/11/06 07:44:34 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14082026/11/06 07:44:34 INFO Uploading ganzbwkdzf6d9lv8q28njw4w811vfbjf-b (256B)14092026/11/06 07:44:34 INFO Uploading g463rg08m4rm28ny0makhbha9qrbj0nd-shared-dep (136B)14102026/11/06 07:44:34 WARN Failed to register uploaded object key=nar/150zc0ff3gz1y07pi4b5q1c5aw1878pbqxzx594v0iqfcqxn5gkx.nar.zst error="server returned 404: 404 page not found\n"14112026/11/06 07:44:34 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14122026/11/06 07:44:34 WARN Failed to register uploaded object key=ahp5avg20hh8hm8vdbja6dx39q1a52sr.ls error="server returned 404: 404 page not found\n"14132026/11/06 07:44:34 WARN Failed to register uploaded object key=g463rg08m4rm28ny0makhbha9qrbj0nd.ls error="server returned 404: 404 page not found\n"14142026/11/06 07:44:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14152026/11/06 07:44:34 WARN Failed to register uploaded object key=ganzbwkdzf6d9lv8q28njw4w811vfbjf.ls error="server returned 404: 404 page not found\n"14162026/11/06 07:44:34 INFO Signed narinfos id=1 count=214172026/11/06 07:44:34 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14182026/11/06 07:44:34 INFO Signed narinfos id=2 count=214192026/11/06 07:44:34 INFO Uploading 4 narinfos1420--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (5.45s)1421=== CONT TestClientIntegration14222026/11/06 07:44:34 WARN Failed to register uploaded object key=ahp5avg20hh8hm8vdbja6dx39q1a52sr.narinfo error="server returned 404: 404 page not found\n"14232026/11/06 07:44:34 WARN Failed to register uploaded object key=ganzbwkdzf6d9lv8q28njw4w811vfbjf.narinfo error="server returned 404: 404 page not found\n"14242026/11/06 07:44:34 WARN Failed to register uploaded object key=g463rg08m4rm28ny0makhbha9qrbj0nd.narinfo error="server returned 404: 404 page not found\n"14252026/11/06 07:44:34 INFO Received uploads request method=POST path=/api/pending_closures1426--- PASS: TestTombstonedObjectOfferedWithoutWaiting (5.47s)1427=== CONT TestClientErrorHandling1428=== RUN TestClientErrorHandling/InvalidStorePath1429=== PAUSE TestClientErrorHandling/InvalidStorePath1430=== RUN TestClientErrorHandling/InvalidAuthToken1431=== PAUSE TestClientErrorHandling/InvalidAuthToken1432=== RUN TestClientErrorHandling/ServerNotAvailable1433=== PAUSE TestClientErrorHandling/ServerNotAvailable1434=== CONT TestClientCADerivations14352026/11/06 07:44:34 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14362026/11/06 07:44:34 WARN Failed to register uploaded object key=g463rg08m4rm28ny0makhbha9qrbj0nd.narinfo error="server returned 404: 404 page not found\n"14372026/11/06 07:44:34 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=014382026/11/06 07:44:34 INFO Vacuumed table table=pending_closures14392026/11/06 07:44:34 INFO Vacuumed table table=pending_objects14402026/11/06 07:44:34 INFO Vacuumed table table=multipart_uploads14412026/11/06 07:44:34 INFO Vacuumed table table=closures14422026/11/06 07:44:34 INFO Completed upload id=1 objects=6 duration=30.902042ms14432026/11/06 07:44:34 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14442026/11/06 07:44:34 INFO Completed upload id=2 objects=6 duration=1.415417ms14452026/11/06 07:44:34 INFO Upload complete. (355ms)1446=== NAME TestClientFallsBackToClosures1447 client_pushes_test.go:112: Retrieved narinfo from S3:1448 StorePath: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientFallsBackToClosures910475453/001/store/g463rg08m4rm28ny0makhbha9qrbj0nd-shared-dep1449 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1450 Compression: zstd1451 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821452 NarSize: 1361453 References: 1454 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1455 client_pushes_test.go:112: Retrieved narinfo from S3:1456 StorePath: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientFallsBackToClosures910475453/001/store/ahp5avg20hh8hm8vdbja6dx39q1a52sr-a1457 URL: nar/150zc0ff3gz1y07pi4b5q1c5aw1878pbqxzx594v0iqfcqxn5gkx.nar.zst1458 Compression: zstd1459 NarHash: sha256:150zc0ff3gz1y07pi4b5q1c5aw1878pbqxzx594v0iqfcqxn5gkx1460 NarSize: 2561461 References: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientFallsBackToClosures910475453/001/store/g463rg08m4rm28ny0makhbha9qrbj0nd-shared-dep1462 CA: text:sha256:1g2cqk658avqm1ak5zabayrl1aw5vhiaycd6rhx6pafkh6z9rwhm1463 client_pushes_test.go:112: Retrieved narinfo from S3:1464 StorePath: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientFallsBackToClosures910475453/001/store/ganzbwkdzf6d9lv8q28njw4w811vfbjf-b1465 URL: nar/150zc0ff3gz1y07pi4b5q1c5aw1878pbqxzx594v0iqfcqxn5gkx.nar.zst1466 Compression: zstd1467 NarHash: sha256:150zc0ff3gz1y07pi4b5q1c5aw1878pbqxzx594v0iqfcqxn5gkx1468 NarSize: 2561469 References: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientFallsBackToClosures910475453/001/store/g463rg08m4rm28ny0makhbha9qrbj0nd-shared-dep1470 CA: text:sha256:1g2cqk658avqm1ak5zabayrl1aw5vhiaycd6rhx6pafkh6z9rwhm14712026/11/06 07:44:34 INFO Vacuumed table table=objects1472--- PASS: TestGCSweepDeliversEachKeyOnce (5.57s)1473=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1474--- PASS: TestClientFallsBackToClosures (6.28s)1475=== CONT TestService_ReadAuthMiddleware14762026/11/06 07:44:34 INFO Received uploads request method=POST path=/api/pending_closures14772026/11/06 07:44:34 INFO Aborted multipart uploads count=0 kept=014782026/11/06 07:44:34 WARN Force mode enabled - objects will be deleted immediately without grace period14792026/11/06 07:44:34 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=014802026/11/06 07:44:34 INFO Vacuumed table table=pending_closures14812026/11/06 07:44:34 INFO Vacuumed table table=pending_objects14822026/11/06 07:44:34 INFO Vacuumed table table=multipart_uploads14832026/11/06 07:44:34 INFO Vacuumed table table=closures14842026/11/06 07:44:34 INFO Vacuumed table table=objects1485--- PASS: TestGCSweepSkipsPendingObjects (5.73s)14862026/11/06 07:44:34 INFO Received uploads request method=POST path=/api/pending_closures1487=== CONT TestService_AuthMiddleware_MTLSProxyHeader1488--- PASS: TestDeduplicatedObjectsRecordedAsPending (5.65s)1489=== CONT TestService_AuthMiddleware14902026/11/06 07:44:35 INFO Aborted multipart uploads count=0 kept=014912026/11/06 07:44:35 WARN Force mode enabled - objects will be deleted immediately without grace period14922026/11/06 07:44:35 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=014932026/11/06 07:44:35 INFO Vacuumed table table=pending_closures14942026/11/06 07:44:35 INFO Vacuumed table table=pending_objects14952026/11/06 07:44:35 INFO Vacuumed table table=multipart_uploads14962026/11/06 07:44:35 INFO Vacuumed table table=closures14972026/11/06 07:44:35 INFO Vacuumed table table=objects1498--- PASS: TestGCMetrics (5.12s)1499=== CONT TestService_ReadScope_PublicByDefault15002026/11/06 07:44:35 INFO Received uploads request method=POST path=/api/pending_closures15012026/11/06 07:44:35 INFO Aborted multipart uploads count=0 kept=015022026/11/06 07:44:35 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=015032026/11/06 07:44:35 INFO Vacuumed table table=pending_closures15042026/11/06 07:44:35 WARN Rate limiter enabled after throttle name=s3-test rate=515052026/11/06 07:44:35 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1506=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1507 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101508 throttle_test.go:215: Rate limiter: enabled=true, rate=5.0015092026/11/06 07:44:35 INFO Vacuumed table table=pending_objects1510--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (9.29s)1511=== CONT TestCacheConfigHandler1512=== RUN TestCacheConfigHandler/full_config,_no_issuer1513=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1514=== RUN TestCacheConfigHandler/no_cache_url_configured1515=== PAUSE TestCacheConfigHandler/no_cache_url_configured1516=== RUN TestCacheConfigHandler/no_signing_keys1517=== PAUSE TestCacheConfigHandler/no_signing_keys1518=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1519=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1520=== CONT TestService_RequireScope_OIDC15212026/11/06 07:44:35 INFO Vacuumed table table=multipart_uploads15222026/11/06 07:44:35 INFO Vacuumed table table=closures15232026/11/06 07:44:35 INFO Vacuumed table table=objects15242026/11/06 07:44:35 INFO Aborted multipart uploads count=0 kept=015252026/11/06 07:44:35 WARN Force mode enabled - objects will be deleted immediately without grace period15262026/11/06 07:44:35 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=015272026/11/06 07:44:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56188/oidc15282026/11/06 07:44:35 INFO Vacuumed table table=pending_closures15292026/11/06 07:44:35 INFO Vacuumed table table=pending_objects15302026/11/06 07:44:35 INFO Vacuumed table table=multipart_uploads15312026/11/06 07:44:35 INFO Vacuumed table table=closures15322026/11/06 07:44:35 INFO Vacuumed table table=objects1533--- PASS: TestPushDedupSurvivesConcurrentGC (5.83s)1534=== CONT TestService_AuthMiddleware_OIDC15352026/11/06 07:44:35 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld3 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1536--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (5.72s)1537=== CONT TestPendingClosureWriteTimeout/empty1538=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline15392026/11/06 07:44:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56192/oidc1540--- PASS: TestGCBugBareHashReferences (5.78s)1541=== CONT TestPendingClosureWriteTimeout/670k_objects1542=== CONT TestPendingClosureWriteTimeout/400_objects1543=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15442026/11/06 07:44:36 INFO Received uploads request method=POST path=/1545=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15462026/11/06 07:44:36 INFO Received complete multipart upload request method=POST path=/1547=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15482026/11/06 07:44:36 INFO Received request for more parts method=POST path=/1549=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15502026/11/06 07:44:36 INFO Received uploads request method=POST path=/1551--- PASS: TestUploadHandlersRejectInvalidKeys (0.06s)1552 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1553 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1554 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1555 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1556=== CONT TestIsValidUploadKey/narinfo1557=== CONT TestIsValidUploadKey/realisation_plus_in_output1558=== CONT TestIsValidUploadKey/unknown_type1559=== CONT TestIsValidUploadKey/empty_key1560=== CONT TestIsValidUploadKey/absolute1561=== CONT TestIsValidUploadKey/traversal_nar1562=== CONT TestIsValidUploadKey/traversal1563=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1564=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1565=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1566=== CONT TestIsValidUploadKey/index.html1567=== CONT TestIsValidUploadKey/nix-cache-info1568=== CONT TestIsValidUploadKey/build_log_home-manager_file1569=== CONT TestIsValidUploadKey/realisation1570=== CONT TestIsValidUploadKey/build_log_equals1571=== CONT TestIsValidUploadKey/build_log_question_mark1572=== CONT TestIsValidUploadKey/build_log_plus_in_name1573=== CONT TestIsValidUploadKey/nar_plain1574=== CONT TestIsValidUploadKey/build_log1575=== CONT TestIsValidUploadKey/listing1576=== CONT TestIsValidUploadKey/nar_xz1577=== CONT TestIsValidUploadKey/nar_zst1578--- PASS: TestIsValidUploadKey (0.07s)1579 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1580 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1581 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1582 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1583 --- PASS: TestIsValidUploadKey/absolute (0.00s)1584 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1585 --- PASS: TestIsValidUploadKey/traversal (0.00s)1586 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1587 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1588 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1589 --- PASS: TestIsValidUploadKey/index.html (0.00s)1590 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1591 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1592 --- PASS: TestIsValidUploadKey/realisation (0.00s)1593 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1594 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1595 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1596 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1597 --- PASS: TestIsValidUploadKey/build_log (0.00s)1598 --- PASS: TestIsValidUploadKey/listing (0.00s)1599 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1600 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1601=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed16022026/11/06 07:44:36 INFO lead: acquired remote=192.0.2.1:123416032026/11/06 07:44:36 INFO lead: acquired remote=192.0.2.1:123416042026/11/06 07:44:36 INFO lead: acquired remote=192.0.2.1:123416052026/11/06 07:44:36 INFO lead: released remote=192.0.2.1:12341606--- PASS: TestLeadIncumbentAnnouncesAtOnce (6.17s)1607=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed16082026/11/06 07:44:37 INFO lead: released remote=192.0.2.1:12341609--- PASS: TestLeadEndsOnShutdown (6.93s)1610=== CONT TestServerTLSConfig/no_client_CA1611=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1612--- PASS: TestCacheStatsHandler (5.27s)1613=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost16142026/11/06 07:44:37 INFO lead: released remote=192.0.2.1:123416152026/11/06 07:44:37 INFO lead: acquired remote=192.0.2.1:12341616--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (6.96s)1617=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed16182026/11/06 07:44:38 INFO Received push request method=POST path=/api/pushes16192026/11/06 07:44:38 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16202026/11/06 07:44:38 INFO Uploading hil6my54sb0w55c529b0fzyfz2pviljb-b (256B)16212026/11/06 07:44:38 INFO Uploading s08800wdwv22awskvv0mq8xjna5zci5n-shared-dep (136B)16222026/11/06 07:44:38 WARN Failed to register uploaded object key=dy655k9xkg3gcr9zl7h1446fmdnk7k2h.ls error="server returned 404: 404 page not found\n"1623=== NAME TestPinProtectsFromGC1624 client_integration_test.go:778: Pinned store path: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestPinProtectsFromGC1231779561/001/store/vx4cw8kpf882nc2psw8n9wgn1kf0ixki-pinned-file.txt16252026/11/06 07:44:38 WARN Failed to register uploaded object key=s08800wdwv22awskvv0mq8xjna5zci5n.ls error="server returned 404: 404 page not found\n"16262026/11/06 07:44:38 WARN Failed to register uploaded object key=hil6my54sb0w55c529b0fzyfz2pviljb.ls error="server returned 404: 404 page not found\n"1627 client_integration_test.go:779: Unpinned store path: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestPinProtectsFromGC1231779561/001/store/fdpxhjfshmyjysz67mw4k0qvc4rx7fc0-unpinned-file.txt16282026/11/06 07:44:38 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16292026/11/06 07:44:38 WARN Failed to register uploaded object key=nar/0ci0zmlcirwggbzv6zwxkv4s3qf5alsfrbkzaahiz2n2b6aa0wl9.nar.zst error="server returned 404: 404 page not found\n"16302026/11/06 07:44:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16312026/11/06 07:44:38 INFO Signed narinfos id=1 count=316322026/11/06 07:44:38 INFO Uploading 3 narinfos16332026/11/06 07:44:38 WARN Failed to register uploaded object key=hil6my54sb0w55c529b0fzyfz2pviljb.narinfo error="server returned 404: 404 page not found\n"16342026/11/06 07:44:38 WARN Failed to register uploaded object key=dy655k9xkg3gcr9zl7h1446fmdnk7k2h.narinfo error="server returned 404: 404 page not found\n"16352026/11/06 07:44:38 INFO Received complete push request method=POST path=/api/pushes/1/complete16362026/11/06 07:44:38 WARN Failed to register uploaded object key=s08800wdwv22awskvv0mq8xjna5zci5n.narinfo error="server returned 404: 404 page not found\n"16372026/11/06 07:44:38 INFO Completed push id=1 objects=8 duration=15.0905ms16382026/11/06 07:44:38 INFO Upload complete. (235ms)1639=== NAME TestClientPushesUseOnePush1640 client_pushes_test.go:97: Retrieved narinfo from S3:1641 StorePath: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientPushesUseOnePush593125151/001/store/s08800wdwv22awskvv0mq8xjna5zci5n-shared-dep1642 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1643 Compression: zstd1644 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821645 NarSize: 1361646 References: 1647 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1648 client_pushes_test.go:97: Retrieved narinfo from S3:1649 StorePath: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientPushesUseOnePush593125151/001/store/dy655k9xkg3gcr9zl7h1446fmdnk7k2h-a1650 URL: nar/0ci0zmlcirwggbzv6zwxkv4s3qf5alsfrbkzaahiz2n2b6aa0wl9.nar.zst1651 Compression: zstd1652 NarHash: sha256:0ci0zmlcirwggbzv6zwxkv4s3qf5alsfrbkzaahiz2n2b6aa0wl91653 NarSize: 2561654 References: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientPushesUseOnePush593125151/001/store/s08800wdwv22awskvv0mq8xjna5zci5n-shared-dep1655 CA: text:sha256:0pp75lw3x57aw12pq8x8cfxgiwzvdjr66a2fdrnz39ghbqmn1jvg1656--- PASS: TestConnectWaitsForAPeerMigration (7.62s)1657=== CONT TestServerTLSConfig/not_a_PEM_file1658=== NAME TestClientPushesUseOnePush1659 client_pushes_test.go:97: Retrieved narinfo from S3:1660 StorePath: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientPushesUseOnePush593125151/001/store/hil6my54sb0w55c529b0fzyfz2pviljb-b1661 URL: nar/0ci0zmlcirwggbzv6zwxkv4s3qf5alsfrbkzaahiz2n2b6aa0wl9.nar.zst1662 Compression: zstd1663 NarHash: sha256:0ci0zmlcirwggbzv6zwxkv4s3qf5alsfrbkzaahiz2n2b6aa0wl91664 NarSize: 2561665 References: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientPushesUseOnePush593125151/001/store/s08800wdwv22awskvv0mq8xjna5zci5n-shared-dep1666 CA: text:sha256:0pp75lw3x57aw12pq8x8cfxgiwzvdjr66a2fdrnz39ghbqmn1jvg16672026/11/06 07:44:38 INFO Received push request method=POST path=/api/pushes1668=== CONT TestServerTLSConfig/missing_CA_file1669--- PASS: TestServerTLSConfig (0.00s)1670 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1671 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1672 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1673=== CONT TestProxyWriteTimeout/narinfo1674=== CONT TestProxyWriteTimeout/10_GiB_nar1675=== CONT TestProxyWriteTimeout/unknown_size1676=== CONT TestProxyWriteTimeout/1_GiB_nar1677=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16782026/11/06 07:44:38 INFO Received uploads request method=POST path=/1679--- PASS: TestProxyWriteTimeout (0.09s)1680 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1681 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1682 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1683 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)16842026/11/06 07:44:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16852026/11/06 07:44:38 INFO Uploading vx4cw8kpf882nc2psw8n9wgn1kf0ixki-pinned-file.txt (128B)16862026/11/06 07:44:38 WARN Failed to register uploaded object key=vx4cw8kpf882nc2psw8n9wgn1kf0ixki.ls error="server returned 404: 404 page not found\n"1687--- PASS: TestClientPushesUseOnePush (6.01s)1688=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16892026/11/06 07:44:38 INFO Received complete multipart upload request method=POST path=/16902026/11/06 07:44:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16912026/11/06 07:44:38 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16922026/11/06 07:44:38 INFO Signed narinfos id=1 count=116932026/11/06 07:44:38 INFO Uploading 1 narinfos1694=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16952026/11/06 07:44:38 INFO Received request for more parts method=POST path=/1696=== CONT TestPush_RejectsBadRequests/no_objects16972026/11/06 07:44:38 INFO Received push request method=POST path=/api/pushes1698=== CONT TestPush_RejectsBadRequests/root_not_in_objects16992026/11/06 07:44:38 INFO Received push request method=POST path=/api/pushes1700=== CONT TestPush_RejectsBadRequests/no_roots17012026/11/06 07:44:38 INFO Received push request method=POST path=/api/pushes17022026/11/06 07:44:38 INFO Received complete push request method=POST path=/api/pushes/1/complete1703=== CONT TestPush_RejectsBadRequests/bad_root17042026/11/06 07:44:38 WARN Failed to register uploaded object key=vx4cw8kpf882nc2psw8n9wgn1kf0ixki.narinfo error="server returned 404: 404 page not found\n"17052026/11/06 07:44:38 INFO Received push request method=POST path=/api/pushes1706=== CONT TestGCEndsOnShutdown/before_the_run1707--- PASS: TestPush_RejectsBadRequests (5.89s)1708 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1709 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1710 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1711 --- PASS: TestPush_RejectsBadRequests/bad_root (0.01s)17122026/11/06 07:44:38 INFO Completed push id=1 objects=3 duration=29.433541ms17132026/11/06 07:44:38 INFO Upload complete. (243ms)17142026/11/06 07:44:38 INFO lead: released remote=192.0.2.1:12341715--- PASS: TestLeadElectsOneAndHandsOver (8.04s)1716=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17172026/11/06 07:44:38 INFO Received push request method=POST path=/api/pushes17182026/11/06 07:44:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17192026/11/06 07:44:38 INFO Uploading fdpxhjfshmyjysz67mw4k0qvc4rx7fc0-unpinned-file.txt (128B)17202026/11/06 07:44:39 WARN Failed to register uploaded object key=fdpxhjfshmyjysz67mw4k0qvc4rx7fc0.ls error="server returned 404: 404 page not found\n"17212026/11/06 07:44:39 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17222026/11/06 07:44:39 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17232026/11/06 07:44:39 INFO Signed narinfos id=2 count=117242026/11/06 07:44:39 INFO Uploading 1 narinfos17252026/11/06 07:44:39 INFO Received push request method=POST path=/api/pushes17262026/11/06 07:44:39 INFO Received complete push request method=POST path=/api/pushes/2/complete17272026/11/06 07:44:39 WARN Failed to register uploaded object key=fdpxhjfshmyjysz67mw4k0qvc4rx7fc0.narinfo error="server returned 404: 404 page not found\n"17282026/11/06 07:44:39 INFO Completed push id=2 objects=3 duration=49.44475ms17292026/11/06 07:44:39 INFO Upload complete. (361ms)1730=== NAME TestClientMultipleUploads1731 client_integration_test.go:405: Created store path 0: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientMultipleUploads566620322/001/store/aplpdhmivvsh7qif31d8v02j2033x0dx-test-file-0.txt17322026/11/06 07:44:39 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)17332026/11/06 07:44:39 INFO Uploading vn2rwm2r8lmlmdihk91ykq7ca5vzzcjn-top (264B)17342026/11/06 07:44:39 INFO Uploading klxqkvb7jdklwak4v5zhvly47i1dg45a-shared-dep (136B)1735=== NAME TestClientWithDependencies1736 client_integration_test.go:660: Built derivation: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientWithDependencies3636990311/001/store/jd5z4kb6wprk5kx0rck7szfnqr6xbc43-test-script17372026/11/06 07:44:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17382026/11/06 07:44:39 WARN Failed to register uploaded object key=klxqkvb7jdklwak4v5zhvly47i1dg45a.ls error="server returned 404: 404 page not found\n"17392026/11/06 07:44:39 WARN Failed to register uploaded object key=nar/0rn2qjkv63pq6wnpmp3bfwxvl08sn92pd3rxsh9qwrxs1d2lh7f9.nar.zst error="server returned 404: 404 page not found\n"17402026/11/06 07:44:39 WARN Failed to register uploaded object key=vn2rwm2r8lmlmdihk91ykq7ca5vzzcjn.ls error="server returned 404: 404 page not found\n"17412026/11/06 07:44:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17422026/11/06 07:44:39 INFO Signed narinfos id=1 count=217432026/11/06 07:44:39 INFO Uploading 2 narinfos17442026/11/06 07:44:39 INFO Starting cleanup of old closures method=DELETE path=/api/closures17452026/11/06 07:44:39 INFO Garbage collection started17462026/11/06 07:44:39 WARN Failed to register uploaded object key=vn2rwm2r8lmlmdihk91ykq7ca5vzzcjn.narinfo error="server returned 404: 404 page not found\n"17472026/11/06 07:44:39 INFO Received complete push request method=POST path=/api/pushes/1/complete17482026/11/06 07:44:39 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"17492026/11/06 07:44:39 WARN mTLS auth: bound subjects configured but subject DN unavailable17502026/11/06 07:44:39 WARN Failed to register uploaded object key=klxqkvb7jdklwak4v5zhvly47i1dg45a.narinfo error="server returned 404: 404 page not found\n"17512026/11/06 07:44:39 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1752--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (4.81s)1753=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete17542026/11/06 07:44:39 INFO Aborted multipart uploads count=0 kept=01755=== NAME TestClientWithDependencies1756 client_integration_test.go:662: Found 1 dependencies (including self)17572026/11/06 07:44:39 INFO Completed push id=1 objects=6 duration=39.953584ms17582026/11/06 07:44:39 INFO Upload complete. (544ms)17592026/11/06 07:44:39 WARN Force mode enabled - objects will be deleted immediately without grace period1760=== NAME TestClientSharedPathCommittedMidPush1761 client_integration_test.go:727: Retrieved narinfo from S3:1762 StorePath: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientSharedPathCommittedMidPush2455297138/001/store/klxqkvb7jdklwak4v5zhvly47i1dg45a-shared-dep1763 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1764 Compression: zstd1765 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821766 NarSize: 1361767 References: 1768 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1769=== NAME TestClientMultipleUploads1770 client_integration_test.go:405: Created store path 1: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientMultipleUploads566620322/001/store/sakz0yr8lkr5cwcq74hf4kjgj1rzxsh5-test-file-1.txt1771=== NAME TestClientSharedPathCommittedMidPush1772 client_integration_test.go:727: Retrieved narinfo from S3:1773 StorePath: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientSharedPathCommittedMidPush2455297138/001/store/vn2rwm2r8lmlmdihk91ykq7ca5vzzcjn-top1774 URL: nar/0rn2qjkv63pq6wnpmp3bfwxvl08sn92pd3rxsh9qwrxs1d2lh7f9.nar.zst1775 Compression: zstd1776 NarHash: sha256:0rn2qjkv63pq6wnpmp3bfwxvl08sn92pd3rxsh9qwrxs1d2lh7f91777 NarSize: 2641778 References: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientSharedPathCommittedMidPush2455297138/001/store/klxqkvb7jdklwak4v5zhvly47i1dg45a-shared-dep1779 CA: text:sha256:1pryrz8s3pjcj1jpah4cqif3p7r1fwzapnssnsz3k6fkkwcc7qff1780--- PASS: TestClientSharedPathCommittedMidPush (6.56s)1781=== CONT TestParseSingleRange/none1782=== CONT TestParseSingleRange/open-ended1783=== CONT TestParseSingleRange/start_far_past_EOF1784=== CONT TestParseSingleRange/start_past_EOF1785=== CONT TestParseSingleRange/single_byte1786=== CONT TestParseSingleRange/suffix_exceeds_size1787=== CONT TestParseSingleRange/suffix1788=== CONT TestParseSingleRange/end_clamped_to_size1789=== CONT TestParseSingleRange/malformed_both_empty1790=== CONT TestParseSingleRange/closed1791=== CONT TestParseSingleRange/malformed_end_before_start1792=== CONT TestParseSingleRange/multi-range_ignored1793=== CONT TestParseSingleRange/malformed_no_dash1794=== CONT TestParseSingleRange/unknown_unit1795--- PASS: TestParseSingleRange (0.01s)1796 --- PASS: TestParseSingleRange/none (0.00s)1797 --- PASS: TestParseSingleRange/open-ended (0.00s)1798 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1799 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1800 --- PASS: TestParseSingleRange/single_byte (0.00s)1801 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1802 --- PASS: TestParseSingleRange/suffix (0.00s)1803 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1804 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1805 --- PASS: TestParseSingleRange/closed (0.00s)1806 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1807 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1808 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1809 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1810=== CONT TestIsValidCachePath/narinfo1811=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1812=== NAME TestClientMultipleUploads1813 client_integration_test.go:405: Created store path 2: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientMultipleUploads566620322/001/store/y3mvy61xva6lv5rqm03jd48qyycjx5ij-test-file-2.txt18142026/11/06 07:44:39 INFO Received push request method=POST path=/api/pushes18152026/11/06 07:44:39 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18162026/11/06 07:44:39 INFO Uploading jd5z4kb6wprk5kx0rck7szfnqr6xbc43-test-script (136B)1817--- PASS: TestUploadHandlersRejectOversizedBody (0.13s)1818 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)1819 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1820 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.00s)1821=== CONT TestIsValidCachePath/short_hash1822=== CONT TestIsValidCachePath/wrong_extension1823=== CONT TestIsValidCachePath/leading_slash1824=== CONT TestIsValidCachePath/empty1825=== CONT TestIsValidCachePath/random_path1826=== CONT TestIsValidCachePath/invalid_char_u1827=== CONT TestIsValidCachePath/invalid_char_e1828=== CONT TestIsValidCachePath/traversal_in_middle1829=== CONT TestIsValidCachePath/traversal_parent1830=== CONT TestIsValidCachePath/index.html1831=== CONT TestIsValidCachePath/nix-cache-info1832=== CONT TestIsValidCachePath/realisation1833=== CONT TestIsValidCachePath/log1834=== CONT TestIsValidCachePath/ls1835=== CONT TestIsValidCachePath/nar_uncompressed1836=== CONT TestIsValidCachePath/nar_bz21837=== CONT TestIsValidCachePath/nar_xz1838=== CONT TestIsValidCachePath/nar_zst1839=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1840=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1841--- PASS: TestIsValidCachePath (0.00s)1842 --- PASS: TestIsValidCachePath/narinfo (0.00s)1843 --- PASS: TestIsValidCachePath/short_hash (0.00s)1844 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1845 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1846 --- PASS: TestIsValidCachePath/empty (0.00s)1847 --- PASS: TestIsValidCachePath/random_path (0.00s)1848 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1849 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1850 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1851 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1852 --- PASS: TestIsValidCachePath/index.html (0.00s)1853 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1854 --- PASS: TestIsValidCachePath/realisation (0.00s)1855 --- PASS: TestIsValidCachePath/log (0.00s)1856 --- PASS: TestIsValidCachePath/ls (0.00s)1857 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1858 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1859 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1860 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1861 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)18622026/11/06 07:44:39 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18632026/11/06 07:44:39 WARN Failed to register uploaded object key=jd5z4kb6wprk5kx0rck7szfnqr6xbc43.ls error="server returned 404: 404 page not found\n"18642026/11/06 07:44:39 WARN Failed to register uploaded object key=log/cy0k7cxyla23krpykbri5zyvfmyjg8hq-test-script.drv error="server returned 404: 404 page not found\n"18652026/11/06 07:44:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18662026/11/06 07:44:39 INFO Signed narinfos id=1 count=118672026/11/06 07:44:39 INFO Uploading 1 narinfos18682026/11/06 07:44:39 INFO Received push request method=POST path=/api/pushes18692026/11/06 07:44:39 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=018702026/11/06 07:44:39 INFO Received complete push request method=POST path=/api/pushes/1/complete18712026/11/06 07:44:39 WARN Failed to register uploaded object key=jd5z4kb6wprk5kx0rck7szfnqr6xbc43.narinfo error="server returned 404: 404 page not found\n"18722026/11/06 07:44:39 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18732026/11/06 07:44:39 INFO Uploading sakz0yr8lkr5cwcq74hf4kjgj1rzxsh5-test-file-1.txt (160B)18742026/11/06 07:44:39 INFO Uploading y3mvy61xva6lv5rqm03jd48qyycjx5ij-test-file-2.txt (160B)18752026/11/06 07:44:39 INFO Completed push id=1 objects=4 duration=16.284417ms18762026/11/06 07:44:39 INFO Uploading aplpdhmivvsh7qif31d8v02j2033x0dx-test-file-0.txt (160B)18772026/11/06 07:44:39 INFO Upload complete. (316ms)1878=== NAME TestClientWithDependencies1879 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientWithDependencies3636990311/001/store) requires matching store prefix18802026/11/06 07:44:39 INFO Vacuumed table table=pending_closures18812026/11/06 07:44:39 WARN Failed to register uploaded object key=sakz0yr8lkr5cwcq74hf4kjgj1rzxsh5.ls error="server returned 404: 404 page not found\n"18822026/11/06 07:44:39 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18832026/11/06 07:44:39 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18842026/11/06 07:44:39 WARN Failed to register uploaded object key=aplpdhmivvsh7qif31d8v02j2033x0dx.ls error="server returned 404: 404 page not found\n"1885=== NAME TestClientCADerivations1886 client_ca_test.go:136: Built CA derivation: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientCADerivations2583501956/001/store/2003di4rmavf1by4zz42sj6mirhx2wyz-ca-test18872026/11/06 07:44:39 INFO Vacuumed table table=pending_objects18882026/11/06 07:44:39 INFO Vacuumed table table=multipart_uploads18892026/11/06 07:44:39 WARN Failed to register uploaded object key=y3mvy61xva6lv5rqm03jd48qyycjx5ij.ls error="server returned 404: 404 page not found\n"18902026/11/06 07:44:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18912026/11/06 07:44:39 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18922026/11/06 07:44:39 INFO Signed narinfos id=1 count=318932026/11/06 07:44:39 INFO Uploading 3 narinfos18942026/11/06 07:44:39 INFO Vacuumed table table=closures1895--- PASS: TestService_ReadAuthMiddleware (5.27s)1896=== CONT TestResolveDBConnectionString/flag_wins1897=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1898=== CONT TestResolveDBConnectionString/nothing_configured1899=== CONT TestResolveDBConnectionString/missing_file_is_an_error1900=== CONT TestResolveDBConnectionString/file_when_flag_empty1901=== CONT TestClientErrorHandling/InvalidStorePath19022026/11/06 07:44:39 WARN Failed to register uploaded object key=sakz0yr8lkr5cwcq74hf4kjgj1rzxsh5.narinfo error="server returned 404: 404 page not found\n"19032026/11/06 07:44:39 INFO Vacuumed table table=objects19042026/11/06 07:44:39 WARN Failed to register uploaded object key=aplpdhmivvsh7qif31d8v02j2033x0dx.narinfo error="server returned 404: 404 page not found\n"1905--- PASS: TestResolveDBConnectionString (0.03s)1906 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1907 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1908 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1909 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1910 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)19112026/11/06 07:44:39 INFO Received complete push request method=POST path=/api/pushes/1/complete19122026/11/06 07:44:39 WARN Failed to register uploaded object key=y3mvy61xva6lv5rqm03jd48qyycjx5ij.narinfo error="server returned 404: 404 page not found\n"1913=== NAME TestClientCADerivations1914 client_ca_test.go:139: Found 1 dependencies (including self)1915--- PASS: TestClientWithDependencies (6.55s)1916=== CONT TestClientErrorHandling/ServerNotAvailable19172026/11/06 07:44:39 INFO Completed push id=1 objects=9 duration=17.137791ms19182026/11/06 07:44:39 INFO Upload complete. (291ms)1919=== NAME TestClientMultipleUploads1920 client_integration_test.go:416: Uploaded 3 paths in 371.169833ms1921=== NAME TestClientIntegration1922 client_integration_test.go:291: Created store path: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientIntegration2164083457/002/store/qlcznkm14indv64pk4f1b0fi8x4xw4ji-test-file.txt1923--- PASS: TestClientMultipleUploads (6.48s)1924=== CONT TestClientErrorHandling/InvalidAuthToken19252026/11/06 07:44:40 INFO Received push request method=POST path=/api/pushes19262026/11/06 07:44:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19272026/11/06 07:44:40 INFO Uploading qlcznkm14indv64pk4f1b0fi8x4xw4ji-test-file.txt (152B)19282026/11/06 07:44:40 INFO Received push request method=POST path=/api/pushes19292026/11/06 07:44:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19302026/11/06 07:44:40 INFO Uploading 2003di4rmavf1by4zz42sj6mirhx2wyz-ca-test (144B)19312026/11/06 07:44:40 WARN Failed to register uploaded object key=qlcznkm14indv64pk4f1b0fi8x4xw4ji.ls error="server returned 404: 404 page not found\n"19322026/11/06 07:44:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19332026/11/06 07:44:40 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19342026/11/06 07:44:40 INFO Signed narinfos id=1 count=119352026/11/06 07:44:40 INFO Uploading 1 narinfos1936--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (5.34s)1937=== CONT TestCacheConfigHandler/full_config,_no_issuer1938=== CONT TestCacheConfigHandler/no_signing_keys1939=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1940=== CONT TestCacheConfigHandler/no_cache_url_configured1941--- PASS: TestCacheConfigHandler (0.00s)1942 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1943 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1944 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1945 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)19462026/11/06 07:44:40 WARN Failed to register uploaded object key=2003di4rmavf1by4zz42sj6mirhx2wyz.ls error="server returned 404: 404 page not found\n"19472026/11/06 07:44:40 INFO Received complete push request method=POST path=/api/pushes/1/complete19482026/11/06 07:44:40 WARN Failed to register uploaded object key=qlcznkm14indv64pk4f1b0fi8x4xw4ji.narinfo error="server returned 404: 404 page not found\n"19492026/11/06 07:44:40 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19502026/11/06 07:44:40 WARN Failed to register uploaded object key=log/lq5ca3wcprfdgb9lh6q7j3iggy9mkav6-ca-test.drv error="server returned 404: 404 page not found\n"19512026/11/06 07:44:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19522026/11/06 07:44:40 INFO Signed narinfos id=1 count=119532026/11/06 07:44:40 INFO Uploading 1 narinfos19542026/11/06 07:44:40 INFO Completed push id=1 objects=3 duration=40.769584ms19552026/11/06 07:44:40 INFO Upload complete. (558ms)19562026/11/06 07:44:40 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/present19572026/11/06 07:44:40 INFO All 1 paths already cached1958=== NAME TestClientIntegration1959 client_integration_test.go:317: Retrieved narinfo from S3:1960 StorePath: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientIntegration2164083457/002/store/qlcznkm14indv64pk4f1b0fi8x4xw4ji-test-file.txt1961 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1962 Compression: zstd19632026/11/06 07:44:40 INFO Received complete push request method=POST path=/api/pushes/1/complete1964 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk119652026/11/06 07:44:40 WARN Failed to register uploaded object key=2003di4rmavf1by4zz42sj6mirhx2wyz.narinfo error="server returned 404: 404 page not found\n"1966 NarSize: 1521967 References: 1968 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11969 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1970 client_integration_test.go:318: Decompressed .ls content (64 bytes):19712026/11/06 07:44:40 INFO Completed push id=1 objects=4 duration=30.22325ms1972 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}19732026/11/06 07:44:40 INFO Upload complete. (712ms)1974=== NAME TestClientCADerivations1975 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientCADerivations2583501956/001/store/2003di4rmavf1by4zz42sj6mirhx2wyz-ca-test1976 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1977 Compression: zstd1978 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1979 NarSize: 1441980 References: 1981 Deriver: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientCADerivations2583501956/001/store/lq5ca3wcprfdgb9lh6q7j3iggy9mkav6-ca-test.drv1982 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1983 client_ca_test.go:185: Checking for realisation files in S3...1984 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1985 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache19862026/11/06 07:44:40 WARN Request failed, retrying attempt=2 backoff=198.481995ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19872026/11/06 07:44:40 WARN Request failed, retrying attempt=3 backoff=399.472501ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19882026/11/06 07:44:40 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1989--- PASS: TestService_AuthMiddleware (5.94s)1990=== NAME TestClientCADerivations1991 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket85?endpoint=http://localhost:55905®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestClientCADerivations2583501956/001/store'1992 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11993--- PASS: TestClientCADerivations (6.70s)19942026/11/06 07:44:41 INFO Received push request method=POST path=/api/pushes19952026/11/06 07:44:41 INFO Object in database but missing from S3 key=qlcznkm14indv64pk4f1b0fi8x4xw4ji.ls19962026/11/06 07:44:41 WARN Found objects in DB but missing from S3, will re-upload count=119972026/11/06 07:44:41 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19982026/11/06 07:44:41 WARN Request failed, retrying attempt=4 backoff=812.2701ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19992026/11/06 07:44:41 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020002026/11/06 07:44:41 INFO Received complete push request method=POST path=/api/pushes/2/complete20012026/11/06 07:44:41 WARN Failed to register uploaded object key=qlcznkm14indv64pk4f1b0fi8x4xw4ji.ls error="server returned 404: 404 page not found\n"20022026/11/06 07:44:41 INFO Completed push id=2 objects=3 duration=745.834µs20032026/11/06 07:44:41 INFO Upload complete. (204ms)2004=== NAME TestClientIntegration2005 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)2006 client_integration_test.go:335: Decompressed .ls content (49 bytes):20072026/11/06 07:44:41 INFO Received create pin request method=POST path=/api/pins/myapp2008 {"version":1,"root":{"type":"regular","size":39}}2009--- PASS: TestService_ReadScope_PublicByDefault (6.25s)20102026/11/06 07:44:41 INFO Created/updated pin name=myapp store_path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestPinProtectsFromGC1231779561/001/store/vx4cw8kpf882nc2psw8n9wgn1kf0ixki-pinned-file.txt narinfo_key=vx4cw8kpf882nc2psw8n9wgn1kf0ixki.narinfo20112026/11/06 07:44:41 INFO Starting cleanup of old closures method=DELETE path=/api/closures20122026/11/06 07:44:41 INFO Garbage collection started20132026/11/06 07:44:41 INFO Aborted multipart uploads count=0 kept=020142026/11/06 07:44:41 WARN Force mode enabled - objects will be deleted immediately without grace period20152026/11/06 07:44:41 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=020162026/11/06 07:44:41 INFO Vacuumed table table=pending_closures20172026/11/06 07:44:41 INFO Vacuumed table table=pending_objects20182026/11/06 07:44:41 INFO Vacuumed table table=multipart_uploads20192026/11/06 07:44:41 INFO Vacuumed table table=closures20202026/11/06 07:44:41 INFO Vacuumed table table=objects20212026/11/06 07:44:42 WARN Request failed, retrying attempt=5 backoff=1.693806726s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20222026/11/06 07:44:42 INFO Received push request method=POST path=/api/pushes20232026/11/06 07:44:42 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20242026/11/06 07:44:42 INFO Received complete push request method=POST path=/api/pushes/3/complete20252026/11/06 07:44:42 WARN Failed to register uploaded object key=qlcznkm14indv64pk4f1b0fi8x4xw4ji.ls error="server returned 404: 404 page not found\n"20262026/11/06 07:44:42 INFO Completed push id=3 objects=3 duration=1.580084ms20272026/11/06 07:44:42 INFO Upload complete. (257ms)2028=== NAME TestClientIntegration2029 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)2030 client_integration_test.go:352: Decompressed .ls content (49 bytes):2031 {"version":1,"root":{"type":"regular","size":39}}2032 client_integration_test.go:363: Testing garbage collection...20332026/11/06 07:44:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures20342026/11/06 07:44:42 INFO Garbage collection started20352026/11/06 07:44:42 INFO Aborted multipart uploads count=0 kept=020362026/11/06 07:44:42 WARN Force mode enabled - objects will be deleted immediately without grace period2037--- PASS: TestDeleteClosuresRacingPins (10.18s)2038=== RUN TestService_RequireScope_OIDC/builder_may_write2039=== PAUSE TestService_RequireScope_OIDC/builder_may_write2040=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2041=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2042=== RUN TestService_RequireScope_OIDC/ops_may_admin2043=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2044=== RUN TestService_RequireScope_OIDC/ops_may_not_write2045=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2046=== RUN TestService_RequireScope_OIDC/reader_may_not_write2047=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2048=== RUN TestService_RequireScope_OIDC/static_token_may_admin2049=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2050=== RUN TestService_RequireScope_OIDC/static_token_may_write2051=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2052=== RUN TestService_RequireScope_OIDC/reader_may_read2053=== PAUSE TestService_RequireScope_OIDC/reader_may_read2054=== RUN TestService_RequireScope_OIDC/writer_implies_read2055=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2056=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2057=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2058=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc2059=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc2060=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2061=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2062=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2063=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2064=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2065=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2066=== CONT TestService_RequireScope_OIDC/builder_may_write2067=== CONT TestService_RequireScope_OIDC/reader_may_read2068=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2069=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20702026/11/06 07:44:42 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]2071=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2072=== CONT TestService_RequireScope_OIDC/static_token_may_write2073=== CONT TestService_RequireScope_OIDC/static_token_may_admin2074=== CONT TestService_RequireScope_OIDC/ops_may_admin2075=== CONT TestService_RequireScope_OIDC/ops_may_not_write2076=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2077=== CONT TestService_RequireScope_OIDC/writer_implies_read2078=== CONT TestService_RequireScope_OIDC/reader_may_not_write2079=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2080=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2081--- PASS: TestService_RequireScope_OIDC (6.62s)2082 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2083 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2084 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2085 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.01s)2086 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2087 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2088 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2089 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2090 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2091 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2092 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2093 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2094 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2095 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)20962026/11/06 07:44:43 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=02097=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2098=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2099=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2100=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2101=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2102=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2103=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2104=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2105=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2106=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected21072026/11/06 07:44:43 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]2108=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2109=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured21102026/11/06 07:44:43 INFO Vacuumed table table=pending_closures21112026/11/06 07:44:43 WARN Authentication failed token_preview=eyJhbGciOi...inlPJPSNKw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2112--- PASS: TestService_AuthMiddleware_OIDC (7.35s)2113 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2114 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.01s)2115 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2116 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.02s)21172026/11/06 07:44:43 INFO Vacuumed table table=pending_objects21182026/11/06 07:44:43 INFO Vacuumed table table=multipart_uploads21192026/11/06 07:44:43 INFO Vacuumed table table=closures21202026/11/06 07:44:43 INFO Vacuumed table table=objects2121=== NAME TestPinProtectsFromGC2122 client_integration_test.go:887: Pin successfully protected closure from garbage collection2123--- PASS: TestPinProtectsFromGC (11.15s)21242026/11/06 07:44:43 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-config21252026/11/06 07:44:43 WARN Request failed, retrying attempt=2 backoff=219.008031ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21262026/11/06 07:44:44 INFO Received uploads request method=POST path=/api/pending_closures21272026/11/06 07:44:44 WARN Request failed, retrying attempt=3 backoff=420.943557ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21282026/11/06 07:44:44 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02129=== NAME TestClientIntegration2130 client_integration_test.go:370: Objects in database after GC:2131 client_integration_test.go:370: Successfully deleted all objects with GC --force2132--- PASS: TestClientIntegration (10.12s)2133=== NAME TestOrphanedObjectsGCStressTest2134 orphaned_objects_gc_test.go:503: Stress test completed successfully:2135 orphaned_objects_gc_test.go:504: - Active objects preserved: 202136 orphaned_objects_gc_test.go:505: - Objects deleted: 2102137 orphaned_objects_gc_test.go:506: - Total GC'd: 2102138--- PASS: TestOrphanedObjectsGCStressTest (27.40s)21392026/11/06 07:44:44 INFO Received uploads request method=POST path=/api/pending_closures21402026/11/06 07:44:44 WARN Request failed, retrying attempt=4 backoff=859.134042ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21412026/11/06 07:44:44 INFO Received uploads request method=POST path=/api/pending_closures21422026/11/06 07:44:44 INFO Received uploads request method=POST path=/api/pending_closures21432026/11/06 07:44:45 INFO Received uploads request method=POST path=/api/pending_closures21442026/11/06 07:44:45 INFO Received uploads request method=POST path=/api/pending_closures21452026/11/06 07:44:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21462026/11/06 07:44:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LjJjN2M2OGYzLTAwZGEtNGYwZS05ZWQyLThkMTkwZjllMTRjNHgxNzkzOTUxMDg0MTY2NjMyMDAw parts=1021472026/11/06 07:44:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21482026/11/06 07:44:45 INFO Completed upload id=1 objects=3 duration=13.705958ms2149--- PASS: TestPendingClosureWriteTimeout (0.00s)2150 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2151 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2152 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2153 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (9.43s)21542026/11/06 07:44:45 WARN Request failed, retrying attempt=5 backoff=1.567121514s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21552026/11/06 07:44:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21562026/11/06 07:44:45 INFO Received uploads request method=POST path=/api/pending_closures21572026/11/06 07:44:45 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21582026/11/06 07:44:45 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21592026/11/06 07:44:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LjAzMDg5NzY4LTg2NjAtNGRiZS05ZWQ1LWIwZmY1ZDQ4NTU4OXgxNzkzOTUxMDg0NzM2MjQwMDAw parts=1021602026/11/06 07:44:45 INFO Aborted multipart uploads count=0 kept=021612026/11/06 07:44:45 WARN Force mode enabled - objects will be deleted immediately without grace period21622026/11/06 07:44:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21632026/11/06 07:44:45 INFO Completed upload id=1 objects=3 duration=6.284791ms21642026/11/06 07:44:45 INFO Received uploads request method=POST path=/api/pending_closures21652026/11/06 07:44:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21662026/11/06 07:44:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LmNjYTMwODdmLWUzYmQtNDk0MS05NDA1LTgzODI3ZTQ0NGZmM3gxNzkzOTUxMDg0ODkxMTM2MDAw parts=1021672026/11/06 07:44:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21682026/11/06 07:44:46 INFO Completed upload id=1 objects=3 duration=5.649208ms21692026/11/06 07:44:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21702026/11/06 07:44:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LjMwNjFiYjYzLTkwY2YtNDJkZi05MjEzLTVkM2YwY2Y5NDA1ZHgxNzkzOTUxMDg1MDQ5OTc4MDAw parts=1021712026/11/06 07:44:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21722026/11/06 07:44:46 INFO Completed upload id=1 objects=3 duration=6.199375ms21732026/11/06 07:44:46 INFO Received uploads request method=POST path=/api/pending_closures21742026/11/06 07:44:46 INFO Received uploads request method=POST path=/api/pending_closures21752026/11/06 07:44:46 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21762026/11/06 07:44:46 WARN Found objects in DB but missing from S3, will re-upload count=121772026/11/06 07:44:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21782026/11/06 07:44:46 INFO Aborted multipart uploads count=0 kept=021792026/11/06 07:44:46 WARN Force mode enabled - objects will be deleted immediately without grace period21802026/11/06 07:44:46 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:55905/bucket104/?delete=\": context canceled"2181--- PASS: TestGCEndsOnShutdown (0.00s)2182 --- PASS: TestGCEndsOnShutdown/before_the_run (6.80s)2183 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (6.97s)2184 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (7.01s)21852026/11/06 07:44:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LjllYzA3ODZhLTRkYWQtNDcwOS1iZTYxLTE1NDllNGMwYjUwNHgxNzkzOTUxMDg1MjQxODk5MDAw parts=1021862026/11/06 07:44:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21872026/11/06 07:44:46 INFO Completed upload id=1 objects=3 duration=3.667334ms21882026/11/06 07:44:46 INFO Received uploads request method=POST path=/api/pending_closures21892026/11/06 07:44:46 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21902026/11/06 07:44:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21912026/11/06 07:44:46 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21922026/11/06 07:44:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LmQ3OTc0NjM4LTczY2QtNDk3Yy1iMWU1LWM5MzZmOTNkYjgzMHgxNzkzOTUxMDg1ODEwMDUwMDAw parts=1021932026/11/06 07:44:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21942026/11/06 07:44:46 INFO Completed upload id=2 objects=3 duration=422.209µs21952026/11/06 07:44:46 INFO Received uploads request method=POST path=/api/pending_closures21962026/11/06 07:44:46 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst21972026/11/06 07:44:46 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo21982026/11/06 07:44:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21992026/11/06 07:44:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=YTY3MzZiMzctNTQ4NC00ZjU3LWFiMzYtN2I3ODg5NmJmNjE3LmU3YTYwY2VlLTRiNzQtNGEyOS04ZDU4LTI3NjkwY2M1YWU1YngxNzkzOTUxMDg2MjA2MTY1MDAw parts=1022002026/11/06 07:44:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22012026/11/06 07:44:46 INFO Completed upload id=2 objects=3 duration=337.417µs22022026/11/06 07:44:46 INFO Received uploads request method=POST path=/api/pending_closures22032026/11/06 07:44:46 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22042026/11/06 07:44:46 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2205--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.08s)2206 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (9.72s)2207 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (8.94s)2208 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (8.26s)2209 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (10.05s)2210 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (9.30s)22112026/11/06 07:44:47 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"22122026/11/06 07:44:47 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-config2213--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2214 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (7.15s)2215 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (7.50s)22162026/11/06 07:44:47 WARN Request failed, retrying attempt=2 backoff=190.812627ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22172026/11/06 07:44:47 WARN Request failed, retrying attempt=3 backoff=369.303072ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22182026/11/06 07:44:47 WARN Request failed, retrying attempt=4 backoff=802.731346ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22192026/11/06 07:44:48 WARN Request failed, retrying attempt=5 backoff=1.622892062s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22202026/11/06 07:44:50 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22212026/11/06 07:44:50 WARN Request failed, retrying attempt=2 backoff=219.785643ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22222026/11/06 07:44:50 WARN Request failed, retrying attempt=3 backoff=379.655943ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22232026/11/06 07:44:50 WARN Request failed, retrying attempt=4 backoff=766.749123ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22242026/11/06 07:44:51 WARN Request failed, retrying attempt=5 backoff=1.711057654s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2225--- PASS: TestClientErrorHandling (0.00s)2226 --- PASS: TestClientErrorHandling/InvalidStorePath (6.16s)2227 --- PASS: TestClientErrorHandling/InvalidAuthToken (6.73s)2228 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.53s)2229PASS2230{"timestamp":"2026-11-06T07:44:53.39048Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56323","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}2231{"timestamp":"2026-11-06T07:44:53.390787Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56389","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(10)"}2232{"timestamp":"2026-11-06T07:44:53.392549Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56402","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(10)"}2233{"timestamp":"2026-11-06T07:44:53.393055Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55981","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)"}2234{"timestamp":"2026-11-06T07:44:53.389015Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56408","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}2235{"timestamp":"2026-11-06T07:44:53.3904Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56418","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}22362026-11-06 07:44:53.554 UTC [94627] LOG: received smart shutdown request22372026-11-06 07:44:53.556 UTC [94627] LOG: background worker "logical replication launcher" (PID 94637) exited with exit code 122382026-11-06 07:44:53.559 UTC [94632] LOG: shutting down22392026-11-06 07:44:53.559 UTC [94632] LOG: checkpoint starting: shutdown immediate22402026-11-06 07:44:55.294 UTC [94632] LOG: checkpoint complete: wrote 12188 buffers (74.4%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.995 s, sync=0.698 s, total=1.735 s; sync files=36060, longest=0.001 s, average=0.001 s; distance=529907 kB, estimate=529907 kB; lsn=0/21D09D88, redo lsn=0/21D09D8822412026-11-06 07:44:55.304 UTC [94627] LOG: database system is shut down2242Running OIDC tests...2243=== RUN TestAudienceForIssuer2244=== PAUSE TestAudienceForIssuer2245=== RUN TestGlobMatch2246=== PAUSE TestGlobMatch2247=== RUN TestValidateToken_ValidToken2248=== PAUSE TestValidateToken_ValidToken2249=== RUN TestValidateToken_WrongAudience2250=== PAUSE TestValidateToken_WrongAudience2251=== RUN TestValidateToken_Expired2252=== PAUSE TestValidateToken_Expired2253=== RUN TestValidateToken_BoundClaimsMismatch2254=== PAUSE TestValidateToken_BoundClaimsMismatch2255=== RUN TestValidateToken_BoundSubjectMismatch2256=== PAUSE TestValidateToken_BoundSubjectMismatch2257=== RUN TestValidateToken_MultipleProviders2258=== PAUSE TestValidateToken_MultipleProviders2259=== RUN TestValidateToken_NoMatchingProvider2260=== PAUSE TestValidateToken_NoMatchingProvider2261=== RUN TestValidateToken_KubernetesServiceAccount2262=== PAUSE TestValidateToken_KubernetesServiceAccount2263=== RUN TestNewValidator_KubernetesRequiresCA2264=== PAUSE TestNewValidator_KubernetesRequiresCA2265=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2266=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2267=== RUN TestPins_ReservedForMatchingRule2268=== PAUSE TestPins_ReservedForMatchingRule2269=== RUN TestPins_TopLevelShorthand2270=== PAUSE TestPins_TopLevelShorthand2271=== RUN TestPins_ConfigValidation2272=== PAUSE TestPins_ConfigValidation2273=== RUN TestScopes_LegacyProviderDefaultsToWrite2274=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2275=== RUN TestScopes_Rules2276=== PAUSE TestScopes_Rules2277=== RUN TestScopes_ConfigValidation2278=== PAUSE TestScopes_ConfigValidation2279=== CONT TestAudienceForIssuer2280--- PASS: TestAudienceForIssuer (0.00s)2281=== CONT TestValidateToken_NoMatchingProvider2282=== CONT TestPins_ConfigValidation2283=== CONT TestPins_ReservedForMatchingRule2284=== CONT TestValidateToken_KubernetesServiceAccount2285=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2286=== CONT TestNewValidator_KubernetesRequiresCA2287--- PASS: TestPins_ConfigValidation (0.00s)2288=== CONT TestScopes_Rules2289=== CONT TestScopes_ConfigValidation2290=== CONT TestPins_TopLevelShorthand2291--- PASS: TestScopes_ConfigValidation (0.00s)2292=== CONT TestValidateToken_Expired2293=== CONT TestValidateToken_MultipleProviders2294=== CONT TestValidateToken_BoundSubjectMismatch2295=== CONT TestValidateToken_BoundClaimsMismatch2296=== CONT TestValidateToken_ValidToken2297=== CONT TestValidateToken_WrongAudience2298=== CONT TestGlobMatch2299=== RUN TestGlobMatch/foo_foo2300=== PAUSE TestGlobMatch/foo_foo2301=== RUN TestGlobMatch/foo_bar2302=== PAUSE TestGlobMatch/foo_bar2303=== RUN TestGlobMatch/*_2304=== PAUSE TestGlobMatch/*_2305=== RUN TestGlobMatch/*_anything2306=== PAUSE TestGlobMatch/*_anything2307=== RUN TestGlobMatch/foo*_foo2308=== PAUSE TestGlobMatch/foo*_foo2309=== RUN TestGlobMatch/foo*_foobar2310=== PAUSE TestGlobMatch/foo*_foobar2311=== RUN TestGlobMatch/foo*_bar2312=== PAUSE TestGlobMatch/foo*_bar2313=== RUN TestGlobMatch/*bar_bar2314=== PAUSE TestGlobMatch/*bar_bar2315=== RUN TestGlobMatch/*bar_foobar2316=== PAUSE TestGlobMatch/*bar_foobar2317=== RUN TestGlobMatch/*bar_foo2318=== PAUSE TestGlobMatch/*bar_foo2319=== RUN TestGlobMatch/foo*bar_foobar2320=== PAUSE TestGlobMatch/foo*bar_foobar2321=== RUN TestGlobMatch/foo*bar_foo123bar2322=== PAUSE TestGlobMatch/foo*bar_foo123bar2323=== RUN TestGlobMatch/foo*bar_foobarbaz2324=== PAUSE TestGlobMatch/foo*bar_foobarbaz2325=== RUN TestGlobMatch/*/*_foo/bar2326=== PAUSE TestGlobMatch/*/*_foo/bar2327=== RUN TestGlobMatch/*/*_foo2328=== PAUSE TestGlobMatch/*/*_foo2329=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2330=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2331=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02332=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02333=== RUN TestGlobMatch/refs/*/main_refs/heads/main2334=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2335=== RUN TestGlobMatch/fo?_foo2336=== PAUSE TestGlobMatch/fo?_foo2337=== RUN TestGlobMatch/fo?_fo2338=== PAUSE TestGlobMatch/fo?_fo2339=== RUN TestGlobMatch/fo?_fooo2340=== PAUSE TestGlobMatch/fo?_fooo2341=== RUN TestGlobMatch/?oo_foo2342=== PAUSE TestGlobMatch/?oo_foo2343=== RUN TestGlobMatch/?oo_boo2344=== PAUSE TestGlobMatch/?oo_boo2345=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2346=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2347=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2348=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2349=== CONT TestGlobMatch/foo_foo2350=== CONT TestScopes_LegacyProviderDefaultsToWrite2351=== CONT TestGlobMatch/*/*_foo/bar2352=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2353=== CONT TestGlobMatch/fo?_foo2354=== CONT TestGlobMatch/foo*bar_foo123bar2355=== CONT TestGlobMatch/foo*bar_foobar2356=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2357=== CONT TestGlobMatch/*bar_foobar2358=== CONT TestGlobMatch/*/*_foo2359=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2360=== CONT TestGlobMatch/foo*_foo2361=== CONT TestGlobMatch/foo*_bar2362=== CONT TestGlobMatch/foo*_foobar2363=== CONT TestGlobMatch/*_2364=== CONT TestGlobMatch/*_anything2365=== CONT TestGlobMatch/foo_bar2366=== CONT TestGlobMatch/*bar_foo2367=== CONT TestGlobMatch/?oo_foo2368=== CONT TestGlobMatch/fo?_fo2369=== CONT TestGlobMatch/*bar_bar2370=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02371=== CONT TestGlobMatch/foo*bar_foobarbaz2372=== CONT TestGlobMatch/refs/*/main_refs/heads/main2373=== CONT TestGlobMatch/fo?_fooo2374=== CONT TestGlobMatch/?oo_boo2375--- PASS: TestGlobMatch (0.00s)2376 --- PASS: TestGlobMatch/foo_foo (0.00s)2377 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2378 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2379 --- PASS: TestGlobMatch/fo?_foo (0.00s)2380 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2381 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2382 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2383 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2384 --- PASS: TestGlobMatch/*/*_foo (0.00s)2385 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2386 --- PASS: TestGlobMatch/foo*_foo (0.00s)2387 --- PASS: TestGlobMatch/foo*_bar (0.00s)2388 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2389 --- PASS: TestGlobMatch/*_ (0.00s)2390 --- PASS: TestGlobMatch/*_anything (0.00s)2391 --- PASS: TestGlobMatch/foo_bar (0.00s)2392 --- PASS: TestGlobMatch/*bar_foo (0.00s)2393 --- PASS: TestGlobMatch/?oo_foo (0.00s)2394 --- PASS: TestGlobMatch/fo?_fo (0.00s)2395 --- PASS: TestGlobMatch/*bar_bar (0.00s)2396 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2397 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2398 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2399 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2400 --- PASS: TestGlobMatch/?oo_boo (0.00s)24012026/11/06 07:44:57 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324022026/11/06 07:44:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56454/oidc2403--- PASS: TestValidateToken_WrongAudience (0.06s)24042026/11/06 07:44:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56448/oidc2405--- PASS: TestValidateToken_ValidToken (0.07s)2406--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.09s)24072026/11/06 07:44:57 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56453/oidc24082026/11/06 07:44:57 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5644724092026/11/06 07:44:57 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:56456/oidc24102026/11/06 07:44:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56459/oidc2411--- PASS: TestValidateToken_KubernetesServiceAccount (0.10s)2412--- PASS: TestValidateToken_MultipleProviders (0.09s)2413--- PASS: TestPins_ReservedForMatchingRule (0.10s)24142026/11/06 07:44:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56465/oidc24152026/11/06 07:44:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56464/oidc24162026/11/06 07:44:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56468/oidc2417--- PASS: TestValidateToken_BoundSubjectMismatch (0.10s)2418--- PASS: TestValidateToken_BoundClaimsMismatch (0.10s)2419--- PASS: TestScopes_Rules (0.11s)24202026/11/06 07:44:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56470/oidc24212026/11/06 07:44:57 http: TLS handshake error from 127.0.0.1:56463: read tcp 127.0.0.1:56462->127.0.0.1:56463: use of closed network connection2422--- PASS: TestNewValidator_KubernetesRequiresCA (0.11s)2423--- PASS: TestPins_TopLevelShorthand (0.11s)24242026/11/06 07:44:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56473/oidc2425--- PASS: TestValidateToken_Expired (0.11s)24262026/11/06 07:44:57 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56461/oidc2427--- PASS: TestValidateToken_NoMatchingProvider (0.15s)24282026/11/06 07:44:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56477/oidc2429--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.13s)2430PASS2431Running hook tests...2432=== RUN TestSendPathsEmpty2433=== PAUSE TestSendPathsEmpty2434=== RUN TestQueueEnqueueAndFetch2435=== PAUSE TestQueueEnqueueAndFetch2436=== RUN TestQueueDeduplication2437=== PAUSE TestQueueDeduplication2438=== RUN TestQueueRemove2439=== PAUSE TestQueueRemove2440=== RUN TestQueueFetchBatchLimit2441=== PAUSE TestQueueFetchBatchLimit2442=== RUN TestQueueRetryMovesToBack2443=== PAUSE TestQueueRetryMovesToBack2444=== RUN TestQueueFetchRemoveLifecycle2445=== PAUSE TestQueueFetchRemoveLifecycle2446=== RUN TestQueueConcurrentWriters2447=== PAUSE TestQueueConcurrentWriters2448=== RUN TestQueueRemoveLargeClosure2449=== PAUSE TestQueueRemoveLargeClosure2450=== RUN TestServerClientIntegration2451--- PASS: TestServerClientIntegration (0.00s)2452=== RUN TestServerQueueError24532026/11/06 07:44:57 ERROR Failed to queue paths error="permission denied" count=12454--- PASS: TestServerQueueError (0.00s)2455=== RUN TestGetListenerSocketActivation2456 server_test.go:145: systemd socket activation does not exist on darwin2457--- SKIP: TestGetListenerSocketActivation (0.00s)2458=== RUN TestServerStalledClientDoesNotBlockShutdown2459=== PAUSE TestServerStalledClientDoesNotBlockShutdown2460=== RUN TestServerBacksOffOnAcceptErrors2461=== PAUSE TestServerBacksOffOnAcceptErrors2462=== RUN TestDrainIsolatesPoisonPath2463=== PAUSE TestDrainIsolatesPoisonPath2464=== RUN TestRunNotBlockedByPoisonHead2465=== PAUSE TestRunNotBlockedByPoisonHead2466=== RUN TestDrainGivesUpWhenServerDown2467=== PAUSE TestDrainGivesUpWhenServerDown2468=== RUN TestFailedPathPrunedByLaterClosure2469=== PAUSE TestFailedPathPrunedByLaterClosure2470=== RUN TestWorkerUploadsAndRemoves2471=== PAUSE TestWorkerUploadsAndRemoves2472=== RUN TestWorkerSkipsGCdPaths2473=== PAUSE TestWorkerSkipsGCdPaths2474=== RUN TestWorkerPrunesClosureDeps2475=== PAUSE TestWorkerPrunesClosureDeps2476=== RUN TestDrainTimeout2477=== PAUSE TestDrainTimeout2478=== RUN TestWorkerRemoveFailureIsNotProgress2479=== PAUSE TestWorkerRemoveFailureIsNotProgress2480=== RUN TestWorkerKeepsPathItCannotStat2481=== PAUSE TestWorkerKeepsPathItCannotStat2482=== CONT TestSendPathsEmpty2483=== CONT TestDrainIsolatesPoisonPath2484=== CONT TestQueueRetryMovesToBack2485--- PASS: TestSendPathsEmpty (0.00s)2486=== CONT TestWorkerRemoveFailureIsNotProgress2487=== CONT TestDrainTimeout2488=== CONT TestWorkerPrunesClosureDeps2489=== CONT TestWorkerSkipsGCdPaths2490=== CONT TestWorkerUploadsAndRemoves2491=== CONT TestFailedPathPrunedByLaterClosure2492=== CONT TestDrainGivesUpWhenServerDown2493=== CONT TestQueueFetchRemoveLifecycle2494=== CONT TestRunNotBlockedByPoisonHead2495=== CONT TestQueueRemove2496=== CONT TestQueueDeduplication2497=== CONT TestQueueEnqueueAndFetch2498=== CONT TestServerStalledClientDoesNotBlockShutdown2499=== CONT TestServerBacksOffOnAcceptErrors25002026/11/06 07:44:57 ERROR Accept failed error="too many open files"2501=== CONT TestQueueRemoveLargeClosure2502=== CONT TestQueueConcurrentWriters2503=== CONT TestQueueFetchBatchLimit2504=== CONT TestWorkerKeepsPathItCannotStat25052026/11/06 07:44:57 ERROR Accept failed error="too many open files"25062026/11/06 07:44:57 INFO Upload queue status pending=325072026/11/06 07:44:57 INFO Uploading batch count=125082026/11/06 07:44:57 ERROR Upload failed error="upload failed" count=125092026/11/06 07:44:57 INFO Uploading batch count=125102026/11/06 07:44:57 ERROR Upload failed error="upload failed" count=12511--- PASS: TestQueueDeduplication (0.01s)25122026/11/06 07:44:57 INFO Upload queue status pending=225132026/11/06 07:44:57 INFO Uploading batch count=125142026/11/06 07:44:57 INFO Uploading batch count=225152026/11/06 07:44:57 ERROR Upload failed error="upload failed" count=225162026/11/06 07:44:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestDrainGivesUpWhenServerDown29963123/002/a25172026/11/06 07:44:57 INFO Upload queue status pending=225182026/11/06 07:44:57 INFO Uploading batch count=225192026/11/06 07:44:57 INFO Uploading batch count=225202026/11/06 07:44:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestDrainGivesUpWhenServerDown29963123/002/b2521--- PASS: TestQueueRemove (0.01s)25222026/11/06 07:44:57 INFO Uploading batch count=12523--- PASS: TestQueueEnqueueAndFetch (0.01s)25242026/11/06 07:44:57 INFO Uploading batch count=225252026/11/06 07:44:57 ERROR Upload failed error="upload failed" count=225262026/11/06 07:44:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestDrainGivesUpWhenServerDown29963123/002/c25272026/11/06 07:44:57 INFO Upload queue status pending=225282026/11/06 07:44:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestDrainGivesUpWhenServerDown29963123/002/d25292026/11/06 07:44:57 INFO Uploading batch count=425302026/11/06 07:44:57 ERROR Upload failed error="upload failed" count=42531--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25322026/11/06 07:44:57 WARN Cannot stat store path, will retry later path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestWorkerKeepsPathItCannotStat535882760/002/locked/aaa error="stat /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestWorkerKeepsPathItCannotStat535882760/002/locked/aaa: permission denied"25332026/11/06 07:44:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestDrainIsolatesPoisonPath3839040847/002/bbb25342026/11/06 07:44:57 INFO Uploading batch count=225352026/11/06 07:44:57 ERROR Upload failed error="upload failed" count=225362026/11/06 07:44:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestDrainGivesUpWhenServerDown29963123/002/e25372026/11/06 07:44:57 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestWorkerSkipsGCdPaths1519168600/002/nonexistent25382026/11/06 07:44:57 INFO Uploading batch count=12539--- PASS: TestQueueRetryMovesToBack (0.02s)25402026/11/06 07:44:57 WARN Cannot stat store path, will retry later path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestWorkerKeepsPathItCannotStat535882760/002/locked/aaa error="stat /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestWorkerKeepsPathItCannotStat535882760/002/locked/aaa: permission denied"25412026/11/06 07:44:57 INFO Uploading batch count=125422026/11/06 07:44:57 WARN Cannot stat store path, will retry later path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestWorkerKeepsPathItCannotStat535882760/002/locked/aaa error="stat /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestWorkerKeepsPathItCannotStat535882760/002/locked/aaa: permission denied"25432026/11/06 07:44:57 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestDrainGivesUpWhenServerDown29963123/002/f25442026/11/06 07:44:57 INFO Uploading batch count=125452026/11/06 07:44:57 ERROR Upload failed error="upload failed" count=125462026/11/06 07:44:57 ERROR Drain finished with paths left in queue remaining=12547--- PASS: TestQueueFetchBatchLimit (0.01s)25482026/11/06 07:44:57 INFO Uploading batch count=125492026/11/06 07:44:57 ERROR Upload failed error="upload failed" count=125502026/11/06 07:44:57 ERROR Drain finished with paths left in queue remaining=1025512026/11/06 07:44:57 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestWorkerRemoveFailureIsNotProgress1802310056/002/nonexistent25522026/11/06 07:44:57 INFO Uploading batch count=125532026/11/06 07:44:57 ERROR Upload failed error="upload failed" count=125542026/11/06 07:44:57 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12555--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)25562026/11/06 07:44:57 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestWorkerRemoveFailureIsNotProgress1802310056/002/nonexistent25572026/11/06 07:44:57 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125582026/11/06 07:44:57 ERROR Drain finished with paths left in queue remaining=12559--- PASS: TestWorkerKeepsPathItCannotStat (0.01s)25602026/11/06 07:44:57 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestWorkerRemoveFailureIsNotProgress1802310056/002/nonexistent25612026/11/06 07:44:57 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125622026/11/06 07:44:57 ERROR Drain finished with paths left in queue remaining=12563--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)2564--- PASS: TestDrainIsolatesPoisonPath (0.02s)2565--- PASS: TestDrainGivesUpWhenServerDown (0.02s)25662026/11/06 07:44:57 ERROR Accept failed error="too many open files"2567--- PASS: TestWorkerPrunesClosureDeps (0.03s)2568--- PASS: TestWorkerUploadsAndRemoves (0.03s)2569--- PASS: TestWorkerSkipsGCdPaths (0.04s)25702026/11/06 07:44:57 ERROR Accept failed error="too many open files"2571--- PASS: TestQueueRemoveLargeClosure (0.04s)2572--- PASS: TestQueueConcurrentWriters (0.04s)25732026/11/06 07:44:57 ERROR Accept failed error="too many open files"25742026/11/06 07:44:57 ERROR Accept failed error="too many open files"25752026/11/06 07:44:57 ERROR Failed to decode request error="read unix /private/var/tb/3/scratch/230fe8f1ab4df694/build/hook2397926165/test.sock->: i/o timeout"25762026/11/06 07:44:57 ERROR Failed to write response error="write unix /private/var/tb/3/scratch/230fe8f1ab4df694/build/hook2397926165/test.sock->: i/o timeout"2577--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)25782026/11/06 07:44:57 ERROR Upload failed error="context deadline exceeded" count=225792026/11/06 07:44:57 ERROR Drain finished with paths left in queue remaining=42580--- PASS: TestDrainTimeout (0.22s)25812026/11/06 07:44:57 ERROR Accept failed error="too many open files"25822026/11/06 07:44:58 ERROR Accept failed error="too many open files"2583--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)25842026/11/06 07:44:58 INFO Uploading batch count=125852026/11/06 07:44:58 INFO Uploading batch count=125862026/11/06 07:44:58 INFO Uploading batch count=125872026/11/06 07:44:58 ERROR Upload failed error="upload failed" count=125882026/11/06 07:44:58 INFO Uploading batch count=125892026/11/06 07:44:58 ERROR Upload failed error="upload failed" count=125902026/11/06 07:44:58 INFO Uploading batch count=125912026/11/06 07:44:58 ERROR Upload failed error="upload failed" count=125922026/11/06 07:44:58 INFO Uploading batch count=125932026/11/06 07:44:58 ERROR Upload failed error="upload failed" count=125942026/11/06 07:44:58 ERROR Drain finished with paths left in queue remaining=12595--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2596PASS2597Running signing tests...2598=== RUN TestExternalSigner2599=== PAUSE TestExternalSigner2600=== RUN TestExternalSignerWrongPublicKey2601=== PAUSE TestExternalSignerWrongPublicKey2602=== RUN TestExternalSignerErrors2603=== PAUSE TestExternalSignerErrors2604=== RUN TestExternalSignerRestartsAfterCrash2605=== PAUSE TestExternalSignerRestartsAfterCrash2606=== RUN TestExternalSignerProgramErrorKeepsProcess2607=== PAUSE TestExternalSignerProgramErrorKeepsProcess2608=== RUN TestExternalSignerClose2609=== PAUSE TestExternalSignerClose2610=== RUN TestExternalSignerRejectsInvalidPublicKey2611=== PAUSE TestExternalSignerRejectsInvalidPublicKey2612=== RUN TestExternalSignerCancellation2613=== PAUSE TestExternalSignerCancellation2614=== RUN TestGenerateFingerprint2615=== PAUSE TestGenerateFingerprint2616=== RUN TestParseSigningKey2617=== PAUSE TestParseSigningKey2618=== RUN TestSign2619=== PAUSE TestSign2620=== RUN TestSignBatch2621=== PAUSE TestSignBatch2622=== RUN TestNilKeyPublicKey2623=== PAUSE TestNilKeyPublicKey2624=== RUN TestSignErrors2625=== PAUSE TestSignErrors2626=== CONT TestExternalSigner2627=== CONT TestExternalSignerCancellation2628=== CONT TestSignBatch2629=== CONT TestSignErrors2630=== CONT TestNilKeyPublicKey2631=== CONT TestExternalSignerProgramErrorKeepsProcess2632=== CONT TestSign2633=== CONT TestGenerateFingerprint2634=== RUN TestGenerateFingerprint/basic_with_references2635=== PAUSE TestGenerateFingerprint/basic_with_references2636=== RUN TestGenerateFingerprint/no_references2637=== PAUSE TestGenerateFingerprint/no_references2638=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2639=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2640=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2641=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2642=== RUN TestGenerateFingerprint/invalid_nar_hash_length2643=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2644=== RUN TestGenerateFingerprint/invalid_store_path_prefix2645=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2646=== RUN TestGenerateFingerprint/invalid_reference_prefix2647=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2648=== CONT TestGenerateFingerprint/basic_with_references2649=== CONT TestExternalSignerErrors2650=== RUN TestExternalSignerErrors/missing_signatures2651=== PAUSE TestExternalSignerErrors/missing_signatures2652=== CONT TestGenerateFingerprint/invalid_nar_hash_length2653=== CONT TestExternalSignerWrongPublicKey2654=== CONT TestExternalSignerRejectsInvalidPublicKey2655=== RUN TestExternalSignerRejectsInvalidPublicKey/#002656=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002657=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2658=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2659=== CONT TestExternalSignerClose2660--- PASS: TestNilKeyPublicKey (0.00s)2661=== CONT TestParseSigningKey2662=== RUN TestParseSigningKey/valid_32-byte_key2663=== PAUSE TestParseSigningKey/valid_32-byte_key2664=== CONT TestGenerateFingerprint/invalid_reference_prefix2665=== CONT TestGenerateFingerprint/invalid_store_path_prefix2666=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2667=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2668=== CONT TestGenerateFingerprint/no_references2669--- PASS: TestGenerateFingerprint (0.00s)2670 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2671 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2672 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2673 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2674 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2675 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2676 --- PASS: TestGenerateFingerprint/no_references (0.00s)2677=== CONT TestExternalSignerRestartsAfterCrash2678=== RUN TestExternalSignerErrors/invalid_JSON2679=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2680=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2681=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2682=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2683=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2684=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2685=== CONT TestExternalSignerRejectsInvalidPublicKey/#002686=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2687=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2688=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2689=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2690=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2691--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2692 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2693 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2694 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2695 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2696 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2697=== PAUSE TestExternalSignerErrors/invalid_JSON2698=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2699=== RUN TestExternalSignerErrors/null_signatures2700=== PAUSE TestExternalSignerErrors/null_signatures2701=== RUN TestParseSigningKey/no_colon2702=== RUN TestExternalSignerErrors/too_few_signatures2703=== PAUSE TestParseSigningKey/no_colon2704=== RUN TestParseSigningKey/empty_name2705=== PAUSE TestParseSigningKey/empty_name2706=== RUN TestParseSigningKey/invalid_base642707=== PAUSE TestParseSigningKey/invalid_base642708=== RUN TestParseSigningKey/wrong_length2709=== PAUSE TestExternalSignerErrors/too_few_signatures2710=== RUN TestExternalSignerErrors/wrong_signature_length2711=== PAUSE TestExternalSignerErrors/wrong_signature_length2712=== RUN TestExternalSignerErrors/program_error2713=== PAUSE TestExternalSignerErrors/program_error2714=== RUN TestExternalSignerErrors/exit_on_request2715=== PAUSE TestExternalSignerErrors/exit_on_request2716=== RUN TestExternalSignerErrors/missing_signature_name2717=== PAUSE TestExternalSignerErrors/missing_signature_name2718=== RUN TestExternalSignerErrors/invalid_signature_base642719=== PAUSE TestExternalSignerErrors/invalid_signature_base642720=== RUN TestSignErrors/nil_key2721=== PAUSE TestParseSigningKey/wrong_length2722=== CONT TestParseSigningKey/valid_32-byte_key2723--- PASS: TestSign (0.00s)2724=== CONT TestParseSigningKey/invalid_base642725=== CONT TestParseSigningKey/wrong_length2726=== RUN TestExternalSignerErrors/wrong_shape2727=== CONT TestParseSigningKey/empty_name2728=== PAUSE TestSignErrors/nil_key2729=== CONT TestParseSigningKey/no_colon2730=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2731--- PASS: TestSignBatch (0.00s)2732=== PAUSE TestExternalSignerErrors/wrong_shape2733=== RUN TestExternalSignerErrors/wrong_id2734=== PAUSE TestExternalSignerErrors/wrong_id2735--- PASS: TestParseSigningKey (0.00s)2736 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2737 --- PASS: TestParseSigningKey/wrong_length (0.00s)2738 --- PASS: TestParseSigningKey/empty_name (0.00s)2739 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2740 --- PASS: TestParseSigningKey/no_colon (0.00s)2741 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2742=== RUN TestSignErrors/nil_narinfo2743=== RUN TestExternalSignerErrors/wrong_signatures_shape2744=== PAUSE TestSignErrors/nil_narinfo2745=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2746=== RUN TestExternalSignerErrors/unrequested_key2747=== RUN TestSignErrors/invalid_narinfo2748=== PAUSE TestSignErrors/invalid_narinfo2749=== RUN TestSignErrors/canceled2750=== PAUSE TestSignErrors/canceled2751=== CONT TestSignErrors/nil_key2752=== PAUSE TestExternalSignerErrors/unrequested_key2753=== RUN TestExternalSignerErrors/wrong_signature_name2754=== PAUSE TestExternalSignerErrors/wrong_signature_name2755=== RUN TestExternalSignerErrors/exit_at_startup2756=== CONT TestSignErrors/invalid_narinfo2757=== CONT TestSignErrors/canceled2758=== CONT TestSignErrors/nil_narinfo2759--- PASS: TestSignErrors (0.00s)2760 --- PASS: TestSignErrors/nil_key (0.00s)2761 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2762 --- PASS: TestSignErrors/canceled (0.00s)2763 --- PASS: TestSignErrors/nil_narinfo (0.00s)2764=== PAUSE TestExternalSignerErrors/exit_at_startup2765=== RUN TestExternalSignerErrors/null2766=== PAUSE TestExternalSignerErrors/null2767=== CONT TestExternalSignerErrors/missing_signatures2768=== CONT TestExternalSignerErrors/invalid_signature_base642769=== CONT TestExternalSignerErrors/unrequested_key2770=== CONT TestExternalSignerErrors/wrong_signature_length2771=== CONT TestExternalSignerErrors/null_signatures2772=== CONT TestExternalSignerErrors/wrong_signatures_shape2773=== CONT TestExternalSignerErrors/invalid_JSON2774=== CONT TestExternalSignerErrors/missing_signature_name2775=== CONT TestExternalSignerErrors/exit_on_request2776=== CONT TestExternalSignerErrors/too_few_signatures2777=== CONT TestExternalSignerErrors/wrong_id2778=== CONT TestExternalSignerErrors/program_error2779=== CONT TestExternalSignerErrors/wrong_shape2780=== CONT TestExternalSignerErrors/exit_at_startup2781=== CONT TestExternalSignerErrors/wrong_signature_name2782=== CONT TestExternalSignerErrors/null2783--- PASS: TestExternalSignerCancellation (0.23s)2784--- PASS: TestExternalSignerRestartsAfterCrash (0.44s)2785/private/var/tb/3/scratch/230fe8f1ab4df694/build/TestExternalSignerRestartsAfterCrash3857705041/001/sign program: line 7: /private/var/tb/3/scratch/230fe8f1ab4df694/build/TestExternalSignerRestartsAfterCrash3857705041/001/sign program.starts: No such file or directory2786--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.61s)2787--- PASS: TestExternalSignerClose (0.80s)2788--- PASS: TestExternalSignerWrongPublicKey (1.94s)2789--- PASS: TestExternalSigner (2.53s)2790--- PASS: TestExternalSignerErrors (0.00s)2791 --- PASS: TestExternalSignerErrors/unrequested_key (0.98s)2792 --- PASS: TestExternalSignerErrors/wrong_shape (1.17s)2793 --- PASS: TestExternalSignerErrors/program_error (1.37s)2794 --- PASS: TestExternalSignerErrors/null_signatures (1.56s)2795 --- PASS: TestExternalSignerErrors/exit_at_startup (1.75s)2796 --- PASS: TestExternalSignerErrors/wrong_signature_length (2.13s)2797 --- PASS: TestExternalSignerErrors/missing_signature_name (2.32s)2798 --- PASS: TestExternalSignerErrors/wrong_id (2.70s)2799 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (2.89s)2800 --- PASS: TestExternalSignerErrors/invalid_JSON (3.08s)2801 --- PASS: TestExternalSignerErrors/exit_on_request (3.27s)2802 --- PASS: TestExternalSignerErrors/missing_signatures (3.47s)2803 --- PASS: TestExternalSignerErrors/wrong_signature_name (3.66s)2804 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (3.85s)2805 --- PASS: TestExternalSignerErrors/too_few_signatures (4.03s)2806 --- PASS: TestExternalSignerErrors/null (4.23s)2807PASS2808Running OpenBao signer tests...2809=== RUN TestSign2810=== PAUSE TestSign2811=== RUN TestSignErrors2812=== PAUSE TestSignErrors2813=== RUN TestServe2814=== PAUSE TestServe2815=== RUN TestServeRejectsGarbage2816=== PAUSE TestServeRejectsGarbage2817=== CONT TestSign2818=== CONT TestServeRejectsGarbage2819=== CONT TestServe2820--- PASS: TestServeRejectsGarbage (0.00s)2821=== CONT TestSignErrors2822=== RUN TestSignErrors/http_error2823=== PAUSE TestSignErrors/http_error2824=== RUN TestSignErrors/invalid_json2825=== PAUSE TestSignErrors/invalid_json2826=== RUN TestSignErrors/no_prefix2827=== PAUSE TestSignErrors/no_prefix2828=== RUN TestSignErrors/invalid_base642829=== PAUSE TestSignErrors/invalid_base642830=== CONT TestSignErrors/http_error2831=== CONT TestSignErrors/no_prefix2832--- PASS: TestServe (0.00s)2833=== CONT TestSignErrors/invalid_base642834=== CONT TestSignErrors/invalid_json2835--- PASS: TestSignErrors (0.00s)2836 --- PASS: TestSignErrors/no_prefix (0.00s)2837 --- PASS: TestSignErrors/http_error (0.00s)2838 --- PASS: TestSignErrors/invalid_json (0.00s)2839 --- PASS: TestSignErrors/invalid_base64 (0.00s)2840--- PASS: TestSign (0.00s)2841PASS