niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #392
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestRegisterUploadedObjectReusesConnections6=== PAUSE TestRegisterUploadedObjectReusesConnections7=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica8=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica9=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun10=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun11=== RUN TestCaseHackSuffix12=== PAUSE TestCaseHackSuffix13=== RUN TestFilterOversizedClosures14=== PAUSE TestFilterOversizedClosures15=== RUN TestUploadMultipart_PartsInParallel16=== PAUSE TestUploadMultipart_PartsInParallel17=== RUN TestPartSizeForNAR18=== PAUSE TestPartSizeForNAR19=== RUN TestUploadMultipart_SupersededByPeer20=== PAUSE TestUploadMultipart_SupersededByPeer21=== RUN TestDumpPathCaseHackMatchesNix22--- PASS: TestDumpPathCaseHackMatchesNix (0.23s)23=== RUN TestDumpPathCaseHackCollision24--- PASS: TestDumpPathCaseHackCollision (0.00s)25=== RUN TestDumpPathMatchesNix26=== PAUSE TestDumpPathMatchesNix27=== RUN TestDumpPathSingleFile28=== PAUSE TestDumpPathSingleFile29=== RUN TestDumpPathWriterError30=== PAUSE TestDumpPathWriterError31=== RUN TestEncodeNixBase3232=== PAUSE TestEncodeNixBase3233=== RUN TestEncodeNixBase32WithRealHash34=== PAUSE TestEncodeNixBase32WithRealHash35=== RUN TestConvertHashToNix3236=== PAUSE TestConvertHashToNix3237=== RUN TestGetStorePathHash38=== PAUSE TestGetStorePathHash39=== RUN TestPathInfoHashCompatibility40=== PAUSE TestPathInfoHashCompatibility41=== RUN TestParsePathInfoJSON42=== PAUSE TestParsePathInfoJSON43=== RUN TestParsePathInfoJSONMultiplePaths44=== PAUSE TestParsePathInfoJSONMultiplePaths45=== RUN TestPathInfoCACompatibility46=== PAUSE TestPathInfoCACompatibility47=== RUN TestRateLimiterFeedback48=== PAUSE TestRateLimiterFeedback49=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess50=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess51=== RUN TestResolveStorePath52=== PAUSE TestResolveStorePath53=== RUN TestDoWithRetry_BodyReplayedViaGetBody54=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody55=== RUN TestShellSplit56=== PAUSE TestShellSplit57=== RUN TestShellSplitErrors58=== PAUSE TestShellSplitErrors59=== RUN TestStreamPushReportsEveryPath60=== PAUSE TestStreamPushReportsEveryPath61=== RUN TestStreamPushBatchesUnderLoad62=== PAUSE TestStreamPushBatchesUnderLoad63=== RUN TestStreamPushIsolatesFailures64=== PAUSE TestStreamPushIsolatesFailures65=== RUN TestStreamPushGivesUpOnDeadServer66=== PAUSE TestStreamPushGivesUpOnDeadServer67=== RUN TestStreamPushRequestLine68=== PAUSE TestStreamPushRequestLine69=== RUN TestStreamPushReportsSignatures70=== PAUSE TestStreamPushReportsSignatures71=== RUN TestClientSignaturesByStorePath72=== PAUSE TestClientSignaturesByStorePath73=== RUN TestSetClientTLS74=== PAUSE TestSetClientTLS75=== RUN TestSetClientTLSDoesNotMutateDefaultTransport76=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport77=== RUN TestSetClientTLSErrors78=== PAUSE TestSetClientTLSErrors79=== RUN TestStaticToken80=== PAUSE TestStaticToken81=== RUN TestFileTokenReadsAndCaches82=== PAUSE TestFileTokenReadsAndCaches83=== RUN TestFileTokenMissing84=== PAUSE TestFileTokenMissing85=== RUN TestFileTokenEmpty86=== PAUSE TestFileTokenEmpty87=== RUN TestScriptTokenNoExpiryRerunsEveryCall88=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall89=== RUN TestScriptTokenCachesUntilRefresh90=== PAUSE TestScriptTokenCachesUntilRefresh91=== RUN TestScriptTokenEmptyToken92=== PAUSE TestScriptTokenEmptyToken93=== RUN TestScriptTokenBadJSON94=== PAUSE TestScriptTokenBadJSON95=== RUN TestScriptTokenScriptFails96=== PAUSE TestScriptTokenScriptFails97=== RUN TestScriptTokenEmptyCommand98=== PAUSE TestScriptTokenEmptyCommand99=== CONT TestDoServerRequestAttachesToken100=== CONT TestShellSplit101=== CONT TestScriptTokenCachesUntilRefresh102=== CONT TestSetClientTLSErrors103=== CONT TestPathInfoHashCompatibility104=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)105=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)106=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon107=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon108=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI109=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI110=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512111=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512112=== CONT TestFileTokenReadsAndCaches113=== CONT TestClientSignaturesByStorePath114=== CONT TestStaticToken115=== CONT TestGetStorePathHash116=== RUN TestGetStorePathHash/valid_store_path117=== PAUSE TestGetStorePathHash/valid_store_path118=== RUN TestGetStorePathHash/basename_without_hyphen_should_error119=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error120=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error121=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error122=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error123=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error124=== CONT TestStreamPushReportsSignatures125=== CONT TestScriptTokenEmptyCommand126=== CONT TestUploadMultipart_PartsInParallel127=== CONT TestScriptTokenNoExpiryRerunsEveryCall128=== CONT TestScriptTokenBadJSON129=== CONT TestEncodeNixBase32130=== RUN TestEncodeNixBase32/test_string_hash131=== CONT TestFileTokenMissing132=== CONT TestDoWithRetry_BodyReplayedViaGetBody133=== CONT TestResolveStorePath134=== CONT TestFileTokenEmpty135=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess136=== CONT TestRateLimiterFeedback137=== CONT TestScriptTokenEmptyToken138=== CONT TestPathInfoCACompatibility139=== CONT TestStreamPushRequestLine140=== CONT TestParsePathInfoJSONMultiplePaths141=== CONT TestSetClientTLSDoesNotMutateDefaultTransport142=== CONT TestParsePathInfoJSON143=== CONT TestSetClientTLS144--- PASS: TestShellSplit (0.00s)145=== CONT TestScriptTokenScriptFails146=== CONT TestEncodeNixBase32WithRealHash147=== CONT TestDumpPathWriterError148=== CONT TestConvertHashToNix32149--- PASS: TestClientSignaturesByStorePath (0.00s)150--- PASS: TestStaticToken (0.00s)151--- PASS: TestScriptTokenEmptyCommand (0.00s)152--- PASS: TestFileTokenReadsAndCaches (0.00s)153--- PASS: TestEncodeNixBase32WithRealHash (0.00s)1542026/10/07 06:18:22 ERROR Upload failed error=boom count=1155--- PASS: TestStreamPushReportsSignatures (0.00s)156=== CONT TestDumpPathMatchesNix157--- PASS: TestFileTokenMissing (0.00s)158=== CONT TestDumpPathSingleFile159=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths160=== RUN TestSetClientTLSErrors/missing_cert_file161--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)162=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths163=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths164=== RUN TestRateLimiterFeedback/429_enables_limiter165=== PAUSE TestRateLimiterFeedback/429_enables_limiter166=== RUN TestRateLimiterFeedback/503_enables_limiter167=== PAUSE TestRateLimiterFeedback/503_enables_limiter168=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter169=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter170=== PAUSE TestEncodeNixBase32/test_string_hash171=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter1722026/10/07 06:18:22 WARN Rate limiter enabled after throttle name=server-test rate=5173=== RUN TestEncodeNixBase32/empty_input174=== PAUSE TestEncodeNixBase32/empty_input175=== CONT TestStreamPushGivesUpOnDeadServer1762026/10/07 06:18:22 ERROR Upload failed error="connection refused" count=201772026/10/07 06:18:22 ERROR Server seems unavailable, giving up on batch untried=17178=== RUN TestParsePathInfoJSON/Nix_format179=== PAUSE TestParsePathInfoJSON/Nix_format180=== RUN TestParsePathInfoJSON/Lix_format181=== PAUSE TestParsePathInfoJSON/Lix_format182=== RUN TestParsePathInfoJSON/empty_input183=== PAUSE TestParsePathInfoJSON/empty_input184=== RUN TestParsePathInfoJSON/whitespace_only185=== CONT TestStreamPushIsolatesFailures186=== RUN TestConvertHashToNix32/SRI_format_to_Nix32187=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32188=== RUN TestConvertHashToNix32/already_Nix32_format189=== PAUSE TestConvertHashToNix32/already_Nix32_format190=== RUN TestConvertHashToNix32/invalid_format191=== PAUSE TestConvertHashToNix32/invalid_format192=== PAUSE TestSetClientTLSErrors/missing_cert_file193=== RUN TestSetClientTLSErrors/missing_key_file194=== PAUSE TestSetClientTLSErrors/missing_key_file195=== RUN TestSetClientTLSErrors/missing_ca_file196=== PAUSE TestSetClientTLSErrors/missing_ca_file197=== RUN TestSetClientTLSErrors/invalid_ca_file198=== PAUSE TestSetClientTLSErrors/invalid_ca_file199--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)200=== PAUSE TestParsePathInfoJSON/whitespace_only201=== RUN TestParsePathInfoJSON/invalid_JSON202=== PAUSE TestParsePathInfoJSON/invalid_JSON203=== CONT TestStreamPushReportsEveryPath204=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths205=== CONT TestUploadMultipart_SupersededByPeer206=== RUN TestUploadMultipart_SupersededByPeer/exists207=== PAUSE TestUploadMultipart_SupersededByPeer/exists208=== RUN TestUploadMultipart_SupersededByPeer/missing209=== PAUSE TestUploadMultipart_SupersededByPeer/missing210=== CONT TestPartSizeForNAR211=== RUN TestPartSizeForNAR/zero_stays_at_minimum212=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum213=== RUN TestPartSizeForNAR/small_stays_at_minimum214=== PAUSE TestPartSizeForNAR/small_stays_at_minimum215=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum2162026/10/07 06:18:22 ERROR Upload failed error="bad path" count=3217=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum218=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts219=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts220=== CONT TestFilterOversizedClosures221=== RUN TestFilterOversizedClosures/no_limit_keeps_everything222=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything223=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped224=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped225=== RUN TestFilterOversizedClosures/all_closures_skipped226=== PAUSE TestFilterOversizedClosures/all_closures_skipped227=== CONT TestCaseHackSuffix228=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)229=== RUN TestPathInfoCACompatibility/null_ca_field230=== PAUSE TestPathInfoCACompatibility/null_ca_field231=== RUN TestPathInfoCACompatibility/old_string_format_-_text232=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text233=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive234=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive235=== RUN TestPathInfoCACompatibility/new_structured_format_-_text236=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text237=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method238=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method239=== RUN TestPartSizeForNAR/1_TiB240=== PAUSE TestPartSizeForNAR/1_TiB241=== RUN TestPartSizeForNAR/5_TiB_S3_max_object242=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object243=== RUN TestPartSizeForNAR/capped_at_5_GiB244=== PAUSE TestPartSizeForNAR/capped_at_5_GiB245=== CONT TestGetStorePathHash/valid_store_path246=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error247=== CONT TestGetStorePathHash/basename_without_hyphen_should_error248=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error249=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512250=== CONT TestEncodeNixBase32/empty_input251=== CONT TestConvertHashToNix32/SRI_format_to_Nix32252=== CONT TestSetClientTLSErrors/missing_cert_file253=== CONT TestParsePathInfoJSON/Nix_format2542026/10/07 06:18:22 ERROR Upload failed error=boom count=1255=== CONT TestConvertHashToNix32/invalid_format256=== CONT TestConvertHashToNix32/already_Nix32_format257=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths258=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI259=== CONT TestUploadMultipart_SupersededByPeer/exists260=== CONT TestSetClientTLSErrors/invalid_ca_file261=== CONT TestStreamPushBatchesUnderLoad262=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter263=== CONT TestShellSplitErrors264=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths265=== CONT TestParsePathInfoJSON/whitespace_only266=== CONT TestSetClientTLSErrors/missing_key_file267=== CONT TestUploadMultipart_SupersededByPeer/missing268=== CONT TestParsePathInfoJSON/invalid_JSON269=== CONT TestParsePathInfoJSON/empty_input270=== CONT TestParsePathInfoJSON/Lix_format271=== CONT TestFilterOversizedClosures/no_limit_keeps_everything272=== CONT TestPathInfoCACompatibility/null_ca_field273=== CONT TestPathInfoCACompatibility/new_structured_format_-_text274=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method275=== CONT TestFilterOversizedClosures/all_closures_skipped2762026/10/07 06:18:22 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=50277=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2782026/10/07 06:18:22 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=2000279=== CONT TestPathInfoCACompatibility/old_string_format_-_text280=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive281=== CONT TestPartSizeForNAR/zero_stays_at_minimum282=== CONT TestPartSizeForNAR/capped_at_5_GiB283=== CONT TestPartSizeForNAR/5_TiB_S3_max_object284=== CONT TestPartSizeForNAR/1_TiB285=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts286=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum287=== CONT TestPartSizeForNAR/small_stays_at_minimum288=== CONT TestRateLimiterFeedback/429_enables_limiter289--- PASS: TestFileTokenEmpty (0.01s)290--- PASS: TestStreamPushReportsEveryPath (0.00s)291--- PASS: TestStreamPushIsolatesFailures (0.00s)292--- PASS: TestDoServerRequestAttachesToken (0.01s)293=== CONT TestRegisterUploadedObjectReusesConnections294=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica295=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon296=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter297=== CONT TestEncodeNixBase32/test_string_hash298--- PASS: TestResolveStorePath (0.00s)299=== CONT TestSetClientTLSErrors/missing_ca_file300=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter301=== CONT TestRateLimiterFeedback/503_enables_limiter302=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun303=== RUN TestSetClientTLS/rejects_connection_without_client_cert304=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert305=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA306=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA307=== RUN TestSetClientTLS/preserves_debug_logging_transport308=== PAUSE TestSetClientTLS/preserves_debug_logging_transport309=== CONT TestSetClientTLS/rejects_connection_without_client_cert310--- PASS: TestGetStorePathHash (0.00s)311 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)312 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)313 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)314 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)315--- PASS: TestEncodeNixBase32 (0.01s)316 --- PASS: TestEncodeNixBase32/empty_input (0.00s)317 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)318--- PASS: TestConvertHashToNix32 (0.00s)319 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)320 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)321 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)322--- PASS: TestPathInfoHashCompatibility (0.00s)323 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)324 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)325 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)326 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)327--- PASS: TestShellSplitErrors (0.00s)328--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)329 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)330 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)3312026/10/07 06:18:22 WARN Rate limiter enabled after throttle name=server-test rate=5332=== CONT TestSetClientTLS/preserves_debug_logging_transport333--- PASS: TestPathInfoCACompatibility (0.00s)334 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)335 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)336 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)337 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)338 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)339--- PASS: TestPartSizeForNAR (0.00s)340 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)341 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)342 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)343 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)344 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)345 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)346 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)347--- PASS: TestParsePathInfoJSON (0.00s)348 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)349 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)350 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)351 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)352 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)353--- PASS: TestScriptTokenScriptFails (0.02s)354=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA355--- PASS: TestSetClientTLSErrors (0.02s)356 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)357 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)358 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)359 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)3602026/10/07 06:18:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:530273612026/10/07 06:18:22 WARN Rate limiter backed off name=server-test rate=53622026/10/07 06:18:22 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:53027363--- PASS: TestFilterOversizedClosures (0.01s)364 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)365 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)366 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)367--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)3682026/10/07 06:18:22 WARN Rate limiter enabled after throttle name=server-test rate=53692026/10/07 06:18:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:530413702026/10/07 06:18:22 WARN Rate limiter backed off name=server-test rate=53712026/10/07 06:18:22 INFO Garbage collection started372--- PASS: TestScriptTokenBadJSON (0.03s)3732026/10/07 06:18:22 INFO Garbage collection started3742026/10/07 06:18:22 WARN Rate limiter enabled after throttle name=server-test rate=53752026/10/07 06:18:22 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:53035376--- PASS: TestStreamPushRequestLine (0.04s)377--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)378 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)379 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.02s)380--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)3812026/10/07 06:18:22 WARN Rate limiter backed off name=server-test rate=5382--- PASS: TestRateLimiterFeedback (0.01s)383 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)384 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)385 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)386 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.02s)3872026/10/07 06:18:22 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=03882026/10/07 06:18:22 WARN Garbage collection finished on another replica. Its statistics are not available here389--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)390--- PASS: TestScriptTokenEmptyToken (0.04s)3912026/10/07 06:18:22 http: TLS handshake error from 127.0.0.1:53113: remote error: tls: bad certificate392--- PASS: TestSetClientTLS (0.02s)393 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.02s)394 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.02s)395 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.04s)396--- PASS: TestScriptTokenCachesUntilRefresh (0.06s)397--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)398--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.08s)399--- PASS: TestDumpPathWriterError (0.09s)400--- PASS: TestDumpPathSingleFile (0.09s)401--- PASS: TestCaseHackSuffix (0.09s)402--- PASS: TestStreamPushBatchesUnderLoad (0.10s)403--- PASS: TestDumpPathMatchesNix (0.15s)404--- PASS: TestUploadMultipart_PartsInParallel (0.65s)405--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)406PASS407Running server tests...408The files belonging to this database system will be owned by user "_tribuchetbld5".409This user must also own the server process.410411The database cluster will be initialized with locale "C".412The default database encoding has accordingly been set to "SQL_ASCII".413The default text search configuration will be set to "english".414415Data page checksums are enabled.416417creating directory /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/postgres2406620678/data ... ok418creating subdirectories ... ok419selecting dynamic shared memory implementation ... posix420selecting default "max_connections" ... 100421selecting default "shared_buffers" ... 128MB422selecting default time zone ... UTC423creating configuration files ... ok424running bootstrap script ... ok425performing post-bootstrap initialization ... ok426syncing data to disk ... ok427428initdb: warning: enabling "trust" authentication for local connections429initdb: 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.430431Success. You can now start the database server using:432433 pg_ctl -D /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/postgres2406620678/data -l logfile start434435/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/postgres2406620678:5432 - no response4362026-10-07 06:18:25.123 UTC [8991] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4372026-10-07 06:18:25.124 UTC [8991] LOG: listening on Unix socket "/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/postgres2406620678/.s.PGSQL.5432"4382026-10-07 06:18:25.128 UTC [8998] LOG: database system was shut down at 2026-10-07 06:18:25 UTC4392026-10-07 06:18:25.130 UTC [8991] LOG: database system is ready to accept connections440/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/postgres2406620678:5432 - accepting connections441{"timestamp":"2026-10-07T06:18:25.369118Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"55cf2985-bfba-422d-a818-f9aada0195fc","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":9,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}442{"timestamp":"2026-10-07T06:18:25.475509Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"0102e852-df96-4d48-9b8b-28abe151f58e","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}443{"timestamp":"2026-10-07T06:18:25.578506Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"5b4777bd-06c4-4a00-aed0-f282007e3e9a","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}444=== RUN TestService_AuthMiddleware445=== PAUSE TestService_AuthMiddleware446=== RUN TestService_AuthMiddleware_MTLSProxyHeader447=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader448=== RUN TestService_AuthMiddleware_MTLSBoundSubjects449=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects450=== RUN TestService_ReadAuthMiddleware451=== PAUSE TestService_ReadAuthMiddleware452=== RUN TestService_AuthMiddleware_OIDC453=== PAUSE TestService_AuthMiddleware_OIDC454=== RUN TestService_RequireScope_OIDC455=== PAUSE TestService_RequireScope_OIDC456=== RUN TestService_ReadScope_PublicByDefault457=== PAUSE TestService_ReadScope_PublicByDefault458=== RUN TestCacheConfigHandler459=== PAUSE TestCacheConfigHandler460=== RUN TestCacheStatsHandler461=== PAUSE TestCacheStatsHandler462=== RUN TestClientCADerivations463=== PAUSE TestClientCADerivations464=== RUN TestClientErrorHandling465=== PAUSE TestClientErrorHandling466=== RUN TestClientIntegration467=== PAUSE TestClientIntegration468=== RUN TestClientMultipleUploads469=== PAUSE TestClientMultipleUploads470=== RUN TestClientWithDependencies471=== PAUSE TestClientWithDependencies472=== RUN TestClientSharedPathCommittedMidPush473=== PAUSE TestClientSharedPathCommittedMidPush474=== RUN TestPinProtectsFromGC475=== PAUSE TestPinProtectsFromGC476=== RUN TestClientPushesUseOnePush477=== PAUSE TestClientPushesUseOnePush478=== RUN TestClientFallsBackToClosures479=== PAUSE TestClientFallsBackToClosures480=== RUN TestDeleteClosuresRacingPins481=== PAUSE TestDeleteClosuresRacingPins482=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock483=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock484=== RUN TestResolveDBConnectionString485=== PAUSE TestResolveDBConnectionString486=== RUN TestConnectWaitsForAPeerMigration487=== PAUSE TestConnectWaitsForAPeerMigration488=== RUN TestLeadElectsOneAndHandsOver489=== PAUSE TestLeadElectsOneAndHandsOver490=== RUN TestLeadIncumbentWinsAfterRestart4912026/10/07 06:18:25 INFO lead: acquired remote=192.0.2.1:12344922026/10/07 06:18:26 INFO lead: released remote=192.0.2.1:12344932026/10/07 06:18:26 INFO lead: acquired remote=192.0.2.1:12344942026/10/07 06:18:27 INFO lead: released remote=192.0.2.1:1234495--- PASS: TestLeadIncumbentWinsAfterRestart (2.01s)496=== RUN TestLeadIncumbentAnnouncesAtOnce497=== PAUSE TestLeadIncumbentAnnouncesAtOnce498=== RUN TestLeadEndsOnShutdown499=== PAUSE TestLeadEndsOnShutdown500=== RUN TestLeadEndsWhenItsConnectionHangs5012026/10/07 06:18:27 INFO lead: acquired remote=192.0.2.1:12345022026-10-07 06:18:29.263 UTC [9050] FATAL: terminating connection due to administrator command5032026/10/07 06:18:29 INFO lead: acquired remote=192.0.2.1:12345042026/10/07 06:18:30 WARN lead: lock connection lost error="timeout: context deadline exceeded"5052026/10/07 06:18:30 INFO lead: released remote=192.0.2.1:12345062026/10/07 06:18:30 INFO lead: released remote=192.0.2.1:1234507--- PASS: TestLeadEndsWhenItsConnectionHangs (2.97s)508=== RUN TestGCAdvisoryLockBlocksConcurrentRun509=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun510=== RUN TestGCBugBareHashReferences511=== PAUSE TestGCBugBareHashReferences512=== RUN TestGCMetrics513=== PAUSE TestGCMetrics514=== RUN TestPushDedupSurvivesConcurrentGC515=== PAUSE TestPushDedupSurvivesConcurrentGC516=== RUN TestDeduplicatedObjectsRecordedAsPending517=== PAUSE TestDeduplicatedObjectsRecordedAsPending518=== RUN TestGCSweepSkipsPendingObjects519=== PAUSE TestGCSweepSkipsPendingObjects520=== RUN TestTombstonedObjectOfferedWithoutWaiting521=== PAUSE TestTombstonedObjectOfferedWithoutWaiting522=== RUN TestGCSweepDeliversEachKeyOnce523=== PAUSE TestGCSweepDeliversEachKeyOnce524=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection525=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection526=== RUN TestForceGCDuringPushOffersSweptObject527=== PAUSE TestForceGCDuringPushOffersSweptObject528=== RUN TestFailedS3DeleteKeepsTombstone529=== PAUSE TestFailedS3DeleteKeepsTombstone530=== RUN TestSweepSkipsRowsLockedByPush531=== PAUSE TestSweepSkipsRowsLockedByPush532=== RUN TestRegisterCompletedObjectNeedsPendingRow533=== PAUSE TestRegisterCompletedObjectNeedsPendingRow534=== RUN TestGetExistingObjectsLocksRows535=== PAUSE TestGetExistingObjectsLocksRows536=== RUN TestSweepRechecksPendingAfterLocking537=== PAUSE TestSweepRechecksPendingAfterLocking538=== RUN TestPushWaitsForSweepHoldingRow539=== PAUSE TestPushWaitsForSweepHoldingRow540=== RUN TestCommitRacingPendingCleanupKeepsObjects541=== PAUSE TestCommitRacingPendingCleanupKeepsObjects542=== RUN TestGCEndsOnShutdown543=== PAUSE TestGCEndsOnShutdown544=== RUN TestGCTaskStore_StartNew545=== PAUSE TestGCTaskStore_StartNew546=== RUN TestGCTaskStore_DeduplicateSameParams547=== PAUSE TestGCTaskStore_DeduplicateSameParams548=== RUN TestGCTaskStore_ConflictDifferentParams549=== PAUSE TestGCTaskStore_ConflictDifferentParams550=== RUN TestGCTaskStore_GetEmpty551=== PAUSE TestGCTaskStore_GetEmpty552=== RUN TestGCTaskStore_GetReturnsLatest553=== PAUSE TestGCTaskStore_GetReturnsLatest554=== RUN TestGCTaskStore_CompletedAllowsNewTask555=== PAUSE TestGCTaskStore_CompletedAllowsNewTask556=== RUN TestGCTaskStore_PhaseUpdates557=== PAUSE TestGCTaskStore_PhaseUpdates558=== RUN TestGCTaskStore_Fail559=== PAUSE TestGCTaskStore_Fail560=== RUN TestGracefulShutdownDrainsInflight561=== PAUSE TestGracefulShutdownDrainsInflight562=== RUN TestService_healthCheckHandler563=== PAUSE TestService_healthCheckHandler564=== RUN TestService_readinessHandler565=== PAUSE TestService_readinessHandler566=== RUN TestGenerateLandingPage567=== PAUSE TestGenerateLandingPage568=== RUN TestCacheConfigHandlerMaxNarSize569=== PAUSE TestCacheConfigHandlerMaxNarSize570=== RUN TestCreatePendingClosureRejectsOversizedNAR571=== PAUSE TestCreatePendingClosureRejectsOversizedNAR572=== RUN TestNARDeduplicationMetadataUploadBug573=== PAUSE TestNARDeduplicationMetadataUploadBug574=== RUN TestMetricsInventory575=== PAUSE TestMetricsInventory576=== RUN TestMetricsCommit577=== PAUSE TestMetricsCommit578=== RUN TestService_NativeMTLS579=== PAUSE TestService_NativeMTLS580=== RUN TestServerTLSConfig581=== PAUSE TestServerTLSConfig582=== RUN TestMultipartCleanup583=== PAUSE TestMultipartCleanup584=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded585=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded586=== RUN TestPendingCleanupUsesOneCutoff587=== PAUSE TestPendingCleanupUsesOneCutoff588=== RUN TestObjectStatsTrigger589=== PAUSE TestObjectStatsTrigger590=== RUN TestObjectStatsLargeCommit591=== PAUSE TestObjectStatsLargeCommit592=== RUN TestOrphanedObjectsGC593=== PAUSE TestOrphanedObjectsGC594=== RUN TestOrphanedObjectsGCStressTest595=== PAUSE TestOrphanedObjectsGCStressTest596=== RUN TestCreatePin_ReservedPins597=== PAUSE TestCreatePin_ReservedPins598=== RUN TestPresentReportsOnlyClosureRoots599=== PAUSE TestPresentReportsOnlyClosureRoots600=== RUN TestPresentRefreshesOnlyStaleClosures601=== PAUSE TestPresentRefreshesOnlyStaleClosures602=== RUN TestPresentNotReportedWhileGCDeletesClosure603=== PAUSE TestPresentNotReportedWhileGCDeletesClosure604=== RUN TestParseSingleRange605=== PAUSE TestParseSingleRange606=== RUN TestProxyHeadersOnlyTrustedOnSocket6072026/10/07 06:18:30 INFO Starting HTTP server address=proxy.sock6082026/10/07 06:18:30 INFO Starting HTTP server address=127.0.0.1:531546092026/10/07 06:18:30 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6102026/10/07 06:18:30 INFO Shutdown signal received, draining in-flight requests timeout=10s611--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.21s)612=== RUN TestIsValidCachePath613=== PAUSE TestIsValidCachePath614=== RUN TestReadProxyNarinfo615=== PAUSE TestReadProxyNarinfo616=== RUN TestReadProxyNarinfoAlreadyDecompressed617=== PAUSE TestReadProxyNarinfoAlreadyDecompressed618=== RUN TestReadProxyContentNegotiation619=== PAUSE TestReadProxyContentNegotiation620=== RUN TestReadProxyNarStreaming621=== PAUSE TestReadProxyNarStreaming622=== RUN TestReadProxy404623=== PAUSE TestReadProxy404624=== RUN TestReadProxyInvalidPath625=== PAUSE TestReadProxyInvalidPath626=== RUN TestReadProxyHead627=== PAUSE TestReadProxyHead628=== RUN TestReadProxyOutlastsServerWriteTimeout629=== PAUSE TestReadProxyOutlastsServerWriteTimeout630=== RUN TestReadProxyConditionalGet631=== PAUSE TestReadProxyConditionalGet632=== RUN TestReadProxyRootRedirectsToIndexHTML633=== PAUSE TestReadProxyRootRedirectsToIndexHTML634=== RUN TestReadProxyDisabled635=== PAUSE TestReadProxyDisabled636=== RUN TestReadRedirectNar637=== PAUSE TestReadRedirectNar638=== RUN TestReadRedirectKeepsNarinfoProxied639=== PAUSE TestReadRedirectKeepsNarinfoProxied640=== RUN TestReadProxyRangeRequest641=== PAUSE TestReadProxyRangeRequest642=== RUN TestReadRedirectUsesPublicS3URL643=== PAUSE TestReadRedirectUsesPublicS3URL644=== RUN TestPush_OverlappingRootsStoreOneRowPerKey645=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey646=== RUN TestPush_CompleteCommitsEveryRoot647=== PAUSE TestPush_CompleteCommitsEveryRoot648=== RUN TestPush_RepeatedRootCommitsOnce649=== PAUSE TestPush_RepeatedRootCommitsOnce650=== RUN TestPush_CompleteWaitsForCleanupOfThePush651=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush652=== RUN TestPush_RootsAreLockedInByteOrder653=== PAUSE TestPush_RootsAreLockedInByteOrder654=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit655=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit656=== RUN TestPush_RejectsBadRequests657=== PAUSE TestPush_RejectsBadRequests658=== RUN TestPush_SignsNarinfosOfItsPendingObjects659=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects660=== RUN TestRedundantMultipartUpload661=== PAUSE TestRedundantMultipartUpload662=== RUN TestCompleteMultipartUpload_ErrorButObjectExists663=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists664=== RUN TestCompletedNarNotReofferedAcrossClosures665=== PAUSE TestCompletedNarNotReofferedAcrossClosures666=== RUN TestPresignedUploadRegisteredBeforeCommit667=== PAUSE TestPresignedUploadRegisteredBeforeCommit668=== RUN TestService_Rustfstest669=== PAUSE TestService_Rustfstest670=== RUN TestParseSize671=== PAUSE TestParseSize672=== RUN TestSkippedUploadsHandler673=== PAUSE TestSkippedUploadsHandler674=== RUN TestSystemdListenerNotActivated675--- PASS: TestSystemdListenerNotActivated (0.00s)676=== RUN TestWatchdogBeatsWhenHealthy677--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)678=== RUN TestWatchdogSkipsWhenUnhealthy6792026/10/07 06:18:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6802026/10/07 06:18:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6812026/10/07 06:18:30 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6822026/10/07 06:18:31 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6832026/10/07 06:18:31 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6842026/10/07 06:18:31 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6852026/10/07 06:18:31 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6862026/10/07 06:18:31 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6872026/10/07 06:18:31 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6882026/10/07 06:18:31 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"689--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)690=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle691=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle692=== RUN TestProxyWriteTimeout693=== PAUSE TestProxyWriteTimeout694=== RUN TestPendingClosureWriteTimeout695=== PAUSE TestPendingClosureWriteTimeout696=== RUN TestIsValidUploadKey697=== PAUSE TestIsValidUploadKey698=== RUN TestUploadHandlersRejectInvalidKeys699=== PAUSE TestUploadHandlersRejectInvalidKeys700=== RUN TestUploadHandlersRejectOversizedBody701=== PAUSE TestUploadHandlersRejectOversizedBody702=== RUN TestService_cleanupPendingClosuresHandler703=== PAUSE TestService_cleanupPendingClosuresHandler704=== RUN TestService_createPendingClosureHandler705=== PAUSE TestService_createPendingClosureHandler706=== RUN TestService_verifyS3Integrity707=== PAUSE TestService_verifyS3Integrity708=== RUN TestCompleteMultipartUnregistered709=== PAUSE TestCompleteMultipartUnregistered710=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT711=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT712=== CONT TestService_AuthMiddleware713=== CONT TestReadRedirectKeepsNarinfoProxied714=== CONT TestDeduplicatedObjectsRecordedAsPending715=== CONT TestPresentReportsOnlyClosureRoots716=== CONT TestPendingCleanupUsesOneCutoff717=== CONT TestPushDedupSurvivesConcurrentGC718=== CONT TestMetricsInventory719=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded720=== CONT TestReadProxyDisabled721=== CONT TestReadProxyRootRedirectsToIndexHTML722=== CONT TestReadProxyConditionalGet723=== CONT TestReadProxyOutlastsServerWriteTimeout724=== CONT TestReadProxyHead725=== CONT TestReadProxyInvalidPath726=== CONT TestReadProxy404727=== CONT TestReadProxyNarStreaming728=== CONT TestReadProxyContentNegotiation729=== CONT TestReadProxyNarinfoAlreadyDecompressed730=== CONT TestReadProxyNarinfo731=== CONT TestIsValidCachePath732=== CONT TestParseSingleRange733=== RUN TestParseSingleRange/none734=== PAUSE TestParseSingleRange/none735=== CONT TestPresentNotReportedWhileGCDeletesClosure736=== CONT TestPresentRefreshesOnlyStaleClosures737=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale738=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale739=== CONT TestReadRedirectNar740=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh741=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh742=== RUN TestIsValidCachePath/narinfo743=== CONT TestMultipartCleanup744=== RUN TestParseSingleRange/unknown_unit745=== PAUSE TestParseSingleRange/unknown_unit746=== PAUSE TestIsValidCachePath/narinfo747=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars748=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars749=== RUN TestIsValidCachePath/nar_zst750=== PAUSE TestIsValidCachePath/nar_zst751=== RUN TestIsValidCachePath/nar_xz752=== PAUSE TestIsValidCachePath/nar_xz753=== RUN TestIsValidCachePath/nar_bz2754=== PAUSE TestIsValidCachePath/nar_bz2755=== RUN TestIsValidCachePath/nar_uncompressed756=== PAUSE TestIsValidCachePath/nar_uncompressed757=== RUN TestIsValidCachePath/ls758=== PAUSE TestIsValidCachePath/ls759=== RUN TestIsValidCachePath/log760=== PAUSE TestIsValidCachePath/log761=== RUN TestIsValidCachePath/realisation762=== PAUSE TestIsValidCachePath/realisation763=== RUN TestIsValidCachePath/nix-cache-info764=== PAUSE TestIsValidCachePath/nix-cache-info765=== RUN TestIsValidCachePath/index.html766=== PAUSE TestIsValidCachePath/index.html767=== RUN TestIsValidCachePath/traversal_parent768=== PAUSE TestIsValidCachePath/traversal_parent769=== RUN TestIsValidCachePath/traversal_in_middle770=== PAUSE TestIsValidCachePath/traversal_in_middle771=== RUN TestIsValidCachePath/invalid_char_e772=== PAUSE TestIsValidCachePath/invalid_char_e773=== RUN TestIsValidCachePath/invalid_char_u774=== PAUSE TestIsValidCachePath/invalid_char_u775=== RUN TestIsValidCachePath/random_path776=== PAUSE TestIsValidCachePath/random_path777=== RUN TestIsValidCachePath/empty778=== PAUSE TestIsValidCachePath/empty779=== RUN TestIsValidCachePath/leading_slash780=== PAUSE TestIsValidCachePath/leading_slash781=== RUN TestIsValidCachePath/wrong_extension782=== PAUSE TestIsValidCachePath/wrong_extension783=== RUN TestIsValidCachePath/short_hash784=== PAUSE TestIsValidCachePath/short_hash785=== RUN TestParseSingleRange/multi-range_ignored786=== PAUSE TestParseSingleRange/multi-range_ignored787=== RUN TestParseSingleRange/malformed_no_dash788=== PAUSE TestParseSingleRange/malformed_no_dash789=== RUN TestParseSingleRange/malformed_both_empty790=== PAUSE TestParseSingleRange/malformed_both_empty791=== RUN TestParseSingleRange/malformed_end_before_start792=== PAUSE TestParseSingleRange/malformed_end_before_start793=== RUN TestParseSingleRange/closed794=== PAUSE TestParseSingleRange/closed795=== RUN TestParseSingleRange/open-ended796=== PAUSE TestParseSingleRange/open-ended797=== RUN TestParseSingleRange/end_clamped_to_size798=== PAUSE TestParseSingleRange/end_clamped_to_size799=== RUN TestParseSingleRange/suffix800=== PAUSE TestParseSingleRange/suffix801=== RUN TestParseSingleRange/suffix_exceeds_size802=== PAUSE TestParseSingleRange/suffix_exceeds_size803=== RUN TestParseSingleRange/single_byte804=== PAUSE TestParseSingleRange/single_byte805=== CONT TestServerTLSConfig806=== RUN TestServerTLSConfig/no_client_CA807=== PAUSE TestServerTLSConfig/no_client_CA808=== RUN TestServerTLSConfig/missing_CA_file809=== PAUSE TestServerTLSConfig/missing_CA_file810=== RUN TestServerTLSConfig/not_a_PEM_file811=== PAUSE TestServerTLSConfig/not_a_PEM_file812=== RUN TestParseSingleRange/start_past_EOF813=== PAUSE TestParseSingleRange/start_past_EOF814=== RUN TestParseSingleRange/start_far_past_EOF815=== PAUSE TestParseSingleRange/start_far_past_EOF816=== CONT TestService_NativeMTLS817=== CONT TestMetricsCommit8182026/10/07 06:18:32 INFO Received push request method=POST path=/api/pushes8192026/10/07 06:18:32 INFO Received complete push request method=POST path=/api/pushes/1/complete8202026/10/07 06:18:32 INFO Completed push id=1 objects=4 duration=33.356958ms8212026/10/07 06:18:32 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete8222026/10/07 06:18:32 INFO Completed upload id=2 objects=2 duration=1.957209ms823--- PASS: TestMetricsCommit (1.60s)824=== CONT TestService_Rustfstest825--- PASS: TestPresentReportsOnlyClosureRoots (2.10s)826=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT827--- PASS: TestReadProxyRootRedirectsToIndexHTML (2.65s)828=== CONT TestCompleteMultipartUnregistered8292026/10/07 06:18:34 INFO Received uploads request method=POST path=/api/pending_closures8302026/10/07 06:18:34 INFO Aborted multipart uploads count=0 kept=08312026/10/07 06:18:34 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=08322026/10/07 06:18:34 INFO Vacuumed table table=pending_closures8332026/10/07 06:18:34 INFO Vacuumed table table=pending_objects8342026/10/07 06:18:34 INFO Vacuumed table table=multipart_uploads8352026/10/07 06:18:34 INFO Received uploads request method=POST path=/api/pending_closures8362026/10/07 06:18:34 INFO Vacuumed table table=closures8372026/10/07 06:18:34 INFO Vacuumed table table=objects8382026/10/07 06:18:34 INFO Aborted multipart uploads count=0 kept=08392026/10/07 06:18:34 WARN Force mode enabled - objects will be deleted immediately without grace period8402026/10/07 06:18: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=08412026/10/07 06:18:34 INFO Vacuumed table table=pending_closures8422026/10/07 06:18:34 INFO Received uploads request method=POST path=/api/pending_closures8432026/10/07 06:18:34 INFO Vacuumed table table=pending_objects8442026/10/07 06:18:34 INFO Vacuumed table table=multipart_uploads8452026/10/07 06:18:34 INFO Vacuumed table table=closures8462026/10/07 06:18:34 INFO Vacuumed table table=objects847--- PASS: TestPushDedupSurvivesConcurrentGC (3.21s)8482026/10/07 06:18:34 INFO Received cleanup request method=DELETE path=/api/pending_closures849=== CONT TestService_verifyS3Integrity8502026/10/07 06:18:34 INFO Received uploads request method=POST path=/api/pending_closures851--- PASS: TestDeduplicatedObjectsRecordedAsPending (3.35s)852=== CONT TestService_createPendingClosureHandler8532026/10/07 06:18:34 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"854--- PASS: TestService_AuthMiddleware (3.49s)855=== CONT TestService_cleanupPendingClosuresHandler856--- PASS: TestReadProxyInvalidPath (3.70s)857=== CONT TestUploadHandlersRejectOversizedBody858=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts859=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts860=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure861=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure862=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart863=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart864=== CONT TestUploadHandlersRejectInvalidKeys865=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info866=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info867=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal868=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal869=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key870=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key871=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key872=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key873=== CONT TestIsValidUploadKey874=== RUN TestIsValidUploadKey/narinfo875=== PAUSE TestIsValidUploadKey/narinfo876=== RUN TestIsValidUploadKey/nar_zst877=== PAUSE TestIsValidUploadKey/nar_zst878=== RUN TestIsValidUploadKey/nar_xz879=== PAUSE TestIsValidUploadKey/nar_xz880=== RUN TestIsValidUploadKey/nar_plain881=== PAUSE TestIsValidUploadKey/nar_plain882=== RUN TestIsValidUploadKey/listing883=== PAUSE TestIsValidUploadKey/listing884=== RUN TestIsValidUploadKey/build_log885=== PAUSE TestIsValidUploadKey/build_log886=== RUN TestIsValidUploadKey/build_log_home-manager_file887=== PAUSE TestIsValidUploadKey/build_log_home-manager_file888=== RUN TestIsValidUploadKey/build_log_plus_in_name889=== PAUSE TestIsValidUploadKey/build_log_plus_in_name890=== RUN TestIsValidUploadKey/build_log_question_mark891=== PAUSE TestIsValidUploadKey/build_log_question_mark892=== RUN TestIsValidUploadKey/build_log_equals893=== PAUSE TestIsValidUploadKey/build_log_equals894=== RUN TestIsValidUploadKey/realisation895=== PAUSE TestIsValidUploadKey/realisation896=== RUN TestIsValidUploadKey/realisation_plus_in_output897=== PAUSE TestIsValidUploadKey/realisation_plus_in_output898=== RUN TestIsValidUploadKey/nix-cache-info899=== PAUSE TestIsValidUploadKey/nix-cache-info900=== RUN TestIsValidUploadKey/index.html901=== PAUSE TestIsValidUploadKey/index.html902=== RUN TestIsValidUploadKey/narinfo_key,_nar_type903=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type904=== RUN TestIsValidUploadKey/nar_key,_narinfo_type905=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type906=== RUN TestIsValidUploadKey/listing_key,_narinfo_type907=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type908=== RUN TestIsValidUploadKey/traversal909=== PAUSE TestIsValidUploadKey/traversal910=== RUN TestIsValidUploadKey/traversal_nar911=== PAUSE TestIsValidUploadKey/traversal_nar912=== RUN TestIsValidUploadKey/absolute913=== PAUSE TestIsValidUploadKey/absolute914=== RUN TestIsValidUploadKey/empty_key915=== PAUSE TestIsValidUploadKey/empty_key916=== RUN TestIsValidUploadKey/unknown_type917=== PAUSE TestIsValidUploadKey/unknown_type918=== CONT TestPendingClosureWriteTimeout919=== RUN TestPendingClosureWriteTimeout/empty920=== PAUSE TestPendingClosureWriteTimeout/empty921=== RUN TestPendingClosureWriteTimeout/400_objects922=== PAUSE TestPendingClosureWriteTimeout/400_objects923=== RUN TestPendingClosureWriteTimeout/670k_objects924=== PAUSE TestPendingClosureWriteTimeout/670k_objects925=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline926=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline927=== CONT TestProxyWriteTimeout928=== RUN TestProxyWriteTimeout/narinfo929=== PAUSE TestProxyWriteTimeout/narinfo930=== RUN TestProxyWriteTimeout/1_GiB_nar931=== PAUSE TestProxyWriteTimeout/1_GiB_nar932=== RUN TestProxyWriteTimeout/10_GiB_nar933=== PAUSE TestProxyWriteTimeout/10_GiB_nar934=== RUN TestProxyWriteTimeout/unknown_size935=== PAUSE TestProxyWriteTimeout/unknown_size936=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle937--- PASS: TestReadRedirectKeepsNarinfoProxied (3.96s)938=== CONT TestSkippedUploadsHandler9392026/10/07 06:18:35 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000940--- PASS: TestSkippedUploadsHandler (0.01s)941=== CONT TestParseSize942--- PASS: TestParseSize (0.00s)943=== CONT TestGCTaskStore_DeduplicateSameParams944--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)945=== CONT TestNARDeduplicationMetadataUploadBug946--- PASS: TestPresentRefreshesOnlyStaleClosures (4.23s)947=== CONT TestCreatePendingClosureRejectsOversizedNAR9482026/10/07 06:18:35 INFO Received uploads request method=POST path=/api/pending_closures949--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)950=== CONT TestCacheConfigHandlerMaxNarSize951--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)952=== CONT TestGenerateLandingPage953--- PASS: TestGenerateLandingPage (0.00s)954=== CONT TestService_readinessHandler955--- PASS: TestReadProxyDisabled (4.42s)956=== CONT TestService_healthCheckHandler9572026/10/07 06:18:35 INFO Received uploads request method=POST path=/api/pending_closures958--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (4.75s)959=== CONT TestGracefulShutdownDrainsInflight9602026/10/07 06:18:35 INFO Starting HTTP server address=127.0.0.1:531999612026/10/07 06:18:35 INFO Shutdown signal received, draining in-flight requests timeout=10s962--- PASS: TestGracefulShutdownDrainsInflight (0.08s)963=== CONT TestGCTaskStore_Fail964--- PASS: TestGCTaskStore_Fail (0.00s)965=== CONT TestGCTaskStore_PhaseUpdates966--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)967=== CONT TestGCTaskStore_CompletedAllowsNewTask968--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)969=== CONT TestGCTaskStore_GetReturnsLatest970--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)971=== CONT TestGCTaskStore_GetEmpty972--- PASS: TestGCTaskStore_GetEmpty (0.00s)973=== CONT TestCreatePin_ReservedPins9742026/10/07 06:18:36 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9752026/10/07 06:18:36 WARN mTLS auth: subject not in bound subjects subject="CN=reader"976--- PASS: TestService_NativeMTLS (4.90s)977=== CONT TestGCTaskStore_ConflictDifferentParams978--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)979=== CONT TestOrphanedObjectsGCStressTest9802026/10/07 06:18:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53201/oidc9812026/10/07 06:18:36 INFO Received uploads request method=POST path=/api/pending_closures9822026/10/07 06:18:36 INFO Received cleanup request method=DELETE path=/api/pending_closures9832026/10/07 06:18:36 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket17/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""9842026/10/07 06:18:36 INFO Aborted multipart uploads count=0 kept=19852026/10/07 06:18:36 INFO Received cleanup request method=DELETE path=/api/pending_closures9862026/10/07 06:18:36 INFO Aborted multipart uploads count=1 kept=0987--- PASS: TestMultipartCleanup (5.36s)988=== CONT TestOrphanedObjectsGC989--- PASS: TestReadProxyNarinfoAlreadyDecompressed (5.37s)990=== CONT TestObjectStatsLargeCommit991--- PASS: TestReadProxyHead (5.61s)992=== CONT TestObjectStatsTrigger993--- PASS: TestMetricsInventory (5.87s)994=== CONT TestRegisterCompletedObjectNeedsPendingRow995--- PASS: TestReadProxyConditionalGet (6.07s)996=== CONT TestPushWaitsForSweepHoldingRow997--- PASS: TestReadRedirectNar (6.30s)998=== CONT TestCommitRacingPendingCleanupKeepsObjects999--- PASS: TestReadProxyNarStreaming (6.53s)1000=== CONT TestSweepRechecksPendingAfterLocking1001--- PASS: TestReadProxyContentNegotiation (7.10s)1002=== CONT TestGCTaskStore_StartNew1003--- PASS: TestGCTaskStore_StartNew (0.00s)1004=== CONT TestGetExistingObjectsLocksRows1005--- PASS: TestReadProxy404 (7.50s)1006=== CONT TestGCEndsOnShutdown1007=== RUN TestGCEndsOnShutdown/before_the_run1008=== PAUSE TestGCEndsOnShutdown/before_the_run1009=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1010=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1011=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1012=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1013=== CONT TestPush_CompleteCommitsEveryRoot10142026/10/07 06:18:38 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1015--- PASS: TestReadProxyNarinfo (7.80s)1016=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit10172026/10/07 06:18:39 INFO Received uploads request method=POST path=/api/pending_closures1018--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (6.06s)1019=== CONT TestPush_RootsAreLockedInByteOrder1020--- PASS: TestService_Rustfstest (6.78s)1021=== CONT TestPresignedUploadRegisteredBeforeCommit10222026/10/07 06:18:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10232026/10/07 06:18:39 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1024--- PASS: TestCompleteMultipartUnregistered (6.08s)1025=== CONT TestPush_CompleteWaitsForCleanupOfThePush10262026/10/07 06:18:40 INFO Received uploads request method=POST path=/api/pending_closures10272026/10/07 06:18:40 INFO Received uploads request method=POST path=/api/pending_closures10282026/10/07 06:18:40 INFO Received uploads request method=POST path=/api/pending_closures10292026/10/07 06:18:40 INFO Aborted multipart uploads count=1 kept=010302026/10/07 06:18:40 INFO Received cleanup request method=DELETE path=/api/pending_closures10312026/10/07 06:18:40 INFO Aborted multipart uploads count=1 kept=01032--- PASS: TestPendingCleanupUsesOneCutoff (9.31s)1033=== CONT TestCompletedNarNotReofferedAcrossClosures10342026/10/07 06:18:40 INFO Received uploads request method=POST path=/api/pending_closures10352026/10/07 06:18:41 INFO Received cleanup request method=DELETE path=/api/pending_closures10362026/10/07 06:18:41 INFO Aborted multipart uploads count=0 kept=010372026/10/07 06:18:41 INFO Received uploads request method=POST path=/api/pending_closures10382026/10/07 06:18:41 INFO Received cleanup request method=DELETE path=/api/pending_closures10392026/10/07 06:18:41 INFO Aborted multipart uploads count=1 kept=010402026/10/07 06:18:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10412026-10-07 06:18:41.170 UTC [9187] ERROR: Closure does not exist: id=110422026-10-07 06:18:41.170 UTC [9187] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10432026-10-07 06:18:41.170 UTC [9187] STATEMENT: -- name: CommitPendingClosure :one1044 SELECT commit_pending_closure($1::bigint)::bigint1045 1046--- PASS: TestService_cleanupPendingClosuresHandler (6.56s)1047=== CONT TestPush_RepeatedRootCommitsOnce10482026/10/07 06:18:41 INFO Received uploads request method=POST path=/api/pending_closures10492026/10/07 06:18:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1050--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.99s)1051=== CONT TestPush_SignsNarinfosOfItsPendingObjects10522026/10/07 06:18:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10532026/10/07 06:18:42 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ODE2OTUzMjQtMzU0ZS00NDlmLWJkNjMtNWRlODFjNzk5YTVlLmI4NmViNDU4LTQyMjAtNDY2YS05ZTRmLWVjOGRiY2EwNWI0MXgxNzkxMzUzOTIwMjM0MTgxMDAw parts=1010542026/10/07 06:18:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10552026/10/07 06:18:42 INFO Completed upload id=1 objects=2 duration=32.055791ms10562026/10/07 06:18:42 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010572026/10/07 06:18:42 INFO Received uploads request method=POST path=/api/pending_closures10582026/10/07 06:18:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures10592026/10/07 06:18:42 WARN readiness check failed error="closed pool"1060--- PASS: TestService_readinessHandler (7.06s)1061=== CONT TestRedundantMultipartUpload1062=== NAME TestNARDeduplicationMetadataUploadBug1063 metadata_upload_test.go:48: First store path: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestNARDeduplicationMetadataUploadBug2356548322/001/store/30s00ph92y3bx5yjvbbccfarbp1dj5rl-file1.txt10642026/10/07 06:18:42 INFO Aborted multipart uploads count=0 kept=010652026/10/07 06:18:42 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=010662026/10/07 06:18:42 INFO Vacuumed table table=pending_closures10672026/10/07 06:18:42 INFO Vacuumed table table=pending_objects10682026/10/07 06:18:42 INFO Vacuumed table table=multipart_uploads10692026/10/07 06:18:42 INFO Vacuumed table table=closures10702026/10/07 06:18:42 INFO Vacuumed table table=objects10712026/10/07 06:18:42 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001072--- PASS: TestService_createPendingClosureHandler (8.14s)1073=== CONT TestClientSharedPathCommittedMidPush10742026/10/07 06:18:42 INFO Received push request method=POST path=/api/pushes10752026/10/07 06:18:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10762026/10/07 06:18:42 INFO Uploading 30s00ph92y3bx5yjvbbccfarbp1dj5rl-file1.txt (160B)10772026/10/07 06:18:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10782026/10/07 06:18:42 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"10792026/10/07 06:18:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10802026/10/07 06:18:42 WARN Failed to register uploaded object key=30s00ph92y3bx5yjvbbccfarbp1dj5rl.ls error="server returned 404: 404 page not found\n"10812026/10/07 06:18:42 INFO Signed narinfos id=1 count=110822026/10/07 06:18:42 INFO Uploading 1 narinfos1083--- PASS: TestService_healthCheckHandler (7.25s)1084=== CONT TestGCMetrics10852026/10/07 06:18:42 INFO Received complete push request method=POST path=/api/pushes/1/complete10862026/10/07 06:18:42 WARN Failed to register uploaded object key=30s00ph92y3bx5yjvbbccfarbp1dj5rl.narinfo error="server returned 404: 404 page not found\n"10872026/10/07 06:18:42 INFO Completed push id=1 objects=3 duration=26.116458ms10882026/10/07 06:18:42 INFO Upload complete. (321ms)1089=== NAME TestNARDeduplicationMetadataUploadBug1090 metadata_upload_test.go:54: Retrieved narinfo from S3:1091 StorePath: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestNARDeduplicationMetadataUploadBug2356548322/001/store/30s00ph92y3bx5yjvbbccfarbp1dj5rl-file1.txt1092 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1093 Compression: zstd1094 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1095 NarSize: 1601096 References: 1097 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf10982026/10/07 06:18:42 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ODE2OTUzMjQtMzU0ZS00NDlmLWJkNjMtNWRlODFjNzk5YTVlLjgxNDk5MjNhLWU1YjktNDA3NS04NjBlLWI4YzNlMDlhOTg1NngxNzkxMzUzOTIwNjgyNDgwMDAw parts=1010992026/10/07 06:18:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1100 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1101 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1102 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11032026/10/07 06:18:42 INFO Completed upload id=1 objects=2 duration=14.666292ms11042026/10/07 06:18:42 INFO Received uploads request method=POST path=/api/pending_closures11052026/10/07 06:18:42 INFO Received uploads request method=POST path=/api/pending_closures11062026/10/07 06:18:42 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11072026/10/07 06:18:42 WARN Found objects in DB but missing from S3, will re-upload count=11108--- PASS: TestService_verifyS3Integrity (8.57s)1109=== CONT TestGCBugBareHashReferences1110=== NAME TestNARDeduplicationMetadataUploadBug1111 metadata_upload_test.go:64: Second store path (same content): /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestNARDeduplicationMetadataUploadBug2356548322/001/store/xy81bn2m3z5zb3vpkdwkzx0rmih396sm-file2.txt11122026/10/07 06:18:43 INFO Received push request method=POST path=/api/pushes11132026/10/07 06:18:43 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11142026/10/07 06:18:43 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11152026/10/07 06:18:43 WARN Failed to register uploaded object key=xy81bn2m3z5zb3vpkdwkzx0rmih396sm.ls error="server returned 404: 404 page not found\n"11162026/10/07 06:18:43 INFO Signed narinfos id=2 count=111172026/10/07 06:18:43 INFO Uploading 1 narinfos11182026/10/07 06:18:43 INFO Received complete push request method=POST path=/api/pushes/2/complete11192026/10/07 06:18:43 WARN Failed to register uploaded object key=xy81bn2m3z5zb3vpkdwkzx0rmih396sm.narinfo error="server returned 404: 404 page not found\n"11202026/10/07 06:18:43 INFO Completed push id=2 objects=3 duration=2.845708ms11212026/10/07 06:18:43 INFO Upload complete. (259ms)1122 metadata_upload_test.go:76: Retrieved narinfo from S3:1123 StorePath: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestNARDeduplicationMetadataUploadBug2356548322/001/store/xy81bn2m3z5zb3vpkdwkzx0rmih396sm-file2.txt1124 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1125 Compression: zstd1126 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1127 NarSize: 1601128 References: 1129 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1130 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1131 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1132 {"version":1,"root":{"type":"regular","size":44}}1133--- PASS: TestNARDeduplicationMetadataUploadBug (8.37s)1134=== CONT TestGCAdvisoryLockBlocksConcurrentRun11352026/10/07 06:18:43 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11362026/10/07 06:18:43 WARN Refused reserved pin name=worker-x86_64-linux11372026/10/07 06:18:43 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11382026/10/07 06:18:43 INFO Received create pin request method=POST path=/api/pins/my-app11392026/10/07 06:18:43 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1140--- PASS: TestCreatePin_ReservedPins (7.54s)1141=== CONT TestLeadEndsOnShutdown1142--- PASS: TestObjectStatsTrigger (7.70s)1143=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1144=== NAME TestOrphanedObjectsGC1145 orphaned_objects_gc_test.go:287: GC Test Summary:1146 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1147 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1148 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1149 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1150 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1151--- PASS: TestOrphanedObjectsGC (8.10s)1152=== CONT TestLeadIncumbentAnnouncesAtOnce1153--- PASS: TestRegisterCompletedObjectNeedsPendingRow (7.70s)1154=== CONT TestPush_RejectsBadRequests11552026/10/07 06:18:44 INFO Received uploads request method=POST path=/api/pending_closures11562026/10/07 06:18:45 WARN Rate limiter enabled after throttle name=s3-test rate=511572026/10/07 06:18:45 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1158=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1159 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101160 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001161--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (10.28s)1162=== CONT TestLeadElectsOneAndHandsOver11632026/10/07 06:18:45 INFO Aborted multipart uploads count=0 kept=011642026/10/07 06:18:45 WARN Force mode enabled - objects will be deleted immediately without grace period11652026/10/07 06:18:45 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=011662026/10/07 06:18:45 INFO Vacuumed table table=pending_closures11672026/10/07 06:18:45 INFO Vacuumed table table=pending_objects11682026/10/07 06:18:45 INFO Vacuumed table table=multipart_uploads11692026/10/07 06:18:45 INFO Vacuumed table table=closures11702026/10/07 06:18:45 INFO Vacuumed table table=objects1171--- PASS: TestPushWaitsForSweepHoldingRow (8.29s)1172=== CONT TestConnectWaitsForAPeerMigration1173--- PASS: TestCommitRacingPendingCleanupKeepsObjects (8.10s)1174=== CONT TestReadRedirectUsesPublicS3URL11752026/10/07 06:18:45 INFO Aborted multipart uploads count=0 kept=011762026/10/07 06:18:45 WARN Force mode enabled - objects will be deleted immediately without grace period11772026/10/07 06:18:45 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=011782026/10/07 06:18:45 INFO Vacuumed table table=pending_closures11792026/10/07 06:18:45 INFO Vacuumed table table=pending_objects11802026/10/07 06:18:45 INFO Vacuumed table table=multipart_uploads11812026/10/07 06:18:45 INFO Vacuumed table table=closures11822026/10/07 06:18:45 INFO Vacuumed table table=objects1183--- PASS: TestSweepRechecksPendingAfterLocking (8.31s)1184=== CONT TestPush_OverlappingRootsStoreOneRowPerKey1185--- PASS: TestGetExistingObjectsLocksRows (7.78s)1186=== CONT TestResolveDBConnectionString1187=== RUN TestResolveDBConnectionString/flag_wins1188=== PAUSE TestResolveDBConnectionString/flag_wins1189=== RUN TestResolveDBConnectionString/file_when_flag_empty1190=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1191=== RUN TestResolveDBConnectionString/missing_file_is_an_error1192=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1193=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1194=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1195=== RUN TestResolveDBConnectionString/nothing_configured1196=== PAUSE TestResolveDBConnectionString/nothing_configured1197=== CONT TestClientFallsBackToClosures11982026/10/07 06:18:46 INFO Received push request method=POST path=/api/pushes11992026/10/07 06:18:46 INFO Received complete push request method=POST path=/api/pushes/1/complete12002026/10/07 06:18:46 INFO Completed push id=1 objects=4 duration=44.016083ms12012026/10/07 06:18:46 INFO Received push request method=POST path=/api/pushes12022026/10/07 06:18:46 INFO Aborted multipart uploads count=0 kept=012032026/10/07 06:18:46 WARN Force mode enabled - objects will be deleted immediately without grace period12042026/10/07 06:18:46 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=012052026/10/07 06:18:46 INFO Vacuumed table table=pending_closures12062026/10/07 06:18:46 INFO Received push request method=POST path=/api/pushes12072026/10/07 06:18:46 INFO Vacuumed table table=pending_objects12082026/10/07 06:18:46 INFO Vacuumed table table=multipart_uploads12092026/10/07 06:18:46 INFO Vacuumed table table=closures12102026/10/07 06:18:46 INFO Vacuumed table table=objects12112026/10/07 06:18:46 INFO Received complete push request method=POST path=/api/pushes/2/complete12122026/10/07 06:18:46 INFO Received complete push request method=POST path=/api/pushes/1/complete12132026/10/07 06:18:46 INFO Completed push id=2 objects=4 duration=10.083375ms1214--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (7.88s)1215=== CONT TestClientPushesUseOnePush12162026/10/07 06:18:46 INFO Completed push id=1 objects=6 duration=44.455792ms1217=== CONT TestPinProtectsFromGC1218--- PASS: TestPush_CompleteCommitsEveryRoot (8.22s)12192026/10/07 06:18:47 INFO Received push request method=POST path=/api/pushes12202026-10-07 06:18:47.218 UTC [9315] ERROR: could not obtain lock on row in relation "closures"12212026-10-07 06:18:47.218 UTC [9315] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12222026-10-07 06:18:47.225 UTC [9315] ERROR: could not obtain lock on row in relation "closures"12232026-10-07 06:18:47.225 UTC [9315] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12242026-10-07 06:18:47.226 UTC [9315] ERROR: could not obtain lock on row in relation "closures"12252026-10-07 06:18:47.226 UTC [9315] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12262026-10-07 06:18:47.233 UTC [9315] ERROR: could not obtain lock on row in relation "closures"12272026-10-07 06:18:47.233 UTC [9315] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12282026-10-07 06:18:47.234 UTC [9315] ERROR: could not obtain lock on row in relation "closures"12292026-10-07 06:18:47.234 UTC [9315] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1230--- PASS: TestPush_RootsAreLockedInByteOrder (7.96s)1231=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock12322026/10/07 06:18:47 INFO Received uploads request method=POST path=/api/pending_closures12332026/10/07 06:18:47 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst12342026/10/07 06:18:47 INFO Received uploads request method=POST path=/api/pending_closures1235--- PASS: TestPresignedUploadRegisteredBeforeCommit (8.00s)1236=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12372026/10/07 06:18:47 INFO Received push request method=POST path=/api/pushes12382026/10/07 06:18:48 INFO Received uploads request method=POST path=/api/pending_closures12392026-10-07 06:18:48.201 UTC [9323] ERROR: Push does not exist: id=112402026-10-07 06:18:48.201 UTC [9323] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE12412026-10-07 06:18:48.201 UTC [9323] STATEMENT: SELECT commit_push($1)1242--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (8.33s)1243=== CONT TestDeleteClosuresRacingPins12442026/10/07 06:18:48 INFO Received push request method=POST path=/api/pushes12452026/10/07 06:18:48 INFO Received complete push request method=POST path=/api/pushes/1/complete12462026/10/07 06:18:48 INFO Completed push id=1 objects=4 duration=38.602083ms1247--- PASS: TestPush_RepeatedRootCommitsOnce (7.55s)1248=== CONT TestSweepSkipsRowsLockedByPush12492026/10/07 06:18:48 INFO Received push request method=POST path=/api/pushes12502026/10/07 06:18:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12512026/10/07 06:18:49 INFO Signed narinfos id=1 count=112522026/10/07 06:18:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12532026/10/07 06:18:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12542026/10/07 06:18:49 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"12552026/10/07 06:18:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12562026/10/07 06:18:49 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"12572026/10/07 06:18:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12582026/10/07 06:18:49 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=112592026/10/07 06:18:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12602026/10/07 06:18:49 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1261--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (7.00s)1262=== CONT TestReadProxyRangeRequest12632026/10/07 06:18:49 INFO Received uploads request method=POST path=/api/pending_closures12642026/10/07 06:18:49 INFO Received uploads request method=POST path=/api/pending_closures12652026/10/07 06:18:50 INFO Aborted multipart uploads count=0 kept=012662026/10/07 06:18:50 WARN Force mode enabled - objects will be deleted immediately without grace period12672026/10/07 06:18:50 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012682026/10/07 06:18:50 INFO Vacuumed table table=pending_closures12692026/10/07 06:18:50 INFO Vacuumed table table=pending_objects12702026/10/07 06:18:50 INFO Vacuumed table table=multipart_uploads12712026/10/07 06:18:50 INFO Vacuumed table table=closures12722026/10/07 06:18:50 INFO Vacuumed table table=objects1273--- PASS: TestGCMetrics (7.54s)1274=== CONT TestFailedS3DeleteKeepsTombstone12752026/10/07 06:18:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12762026/10/07 06:18:50 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ODE2OTUzMjQtMzU0ZS00NDlmLWJkNjMtNWRlODFjNzk5YTVlLjQwYzVhNzAwLWI2MTgtNDMxOC1iNjlmLTIwNDBjYzQ2ZWRiNXgxNzkxMzUzOTI4MjEyNjA3MDAw parts=1212772026/10/07 06:18:50 INFO Received uploads request method=POST path=/api/pending_closures1278--- PASS: TestCompletedNarNotReofferedAcrossClosures (10.23s)1279=== CONT TestForceGCDuringPushOffersSweptObject1280=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1281=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1282=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1283=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1284=== CONT TestTombstonedObjectOfferedWithoutWaiting12852026/10/07 06:18:50 INFO Received push request method=POST path=/api/pushes12862026/10/07 06:18:50 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12872026/10/07 06:18:50 INFO Uploading 9wqqqsl3d8y950zndqn5l15vwj3xvwk4-shared-dep (136B)12882026/10/07 06:18:50 INFO Uploading bjvw1jb5q3ds4bq3hnsq2i8khyq1gnba-top (280B)12892026/10/07 06:18:50 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12902026/10/07 06:18:50 WARN Failed to register uploaded object key=9wqqqsl3d8y950zndqn5l15vwj3xvwk4.ls error="server returned 404: 404 page not found\n"12912026/10/07 06:18:50 WARN Failed to register uploaded object key=bjvw1jb5q3ds4bq3hnsq2i8khyq1gnba.ls error="server returned 404: 404 page not found\n"12922026/10/07 06:18:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12932026/10/07 06:18:50 WARN Failed to register uploaded object key=nar/0b19yfmym4rj71w4y41r32gswgiigy5xbnykvzvqk8lbwb9rr3lx.nar.zst error="server returned 404: 404 page not found\n"12942026/10/07 06:18:50 INFO Signed narinfos id=1 count=212952026/10/07 06:18:50 INFO Uploading 2 narinfos12962026/10/07 06:18:50 WARN Failed to register uploaded object key=bjvw1jb5q3ds4bq3hnsq2i8khyq1gnba.narinfo error="server returned 404: 404 page not found\n"12972026/10/07 06:18:50 INFO Received complete push request method=POST path=/api/pushes/1/complete12982026/10/07 06:18:50 WARN Failed to register uploaded object key=9wqqqsl3d8y950zndqn5l15vwj3xvwk4.narinfo error="server returned 404: 404 page not found\n"12992026/10/07 06:18:50 INFO Completed push id=1 objects=6 duration=19.097417ms13002026/10/07 06:18:50 INFO Upload complete. (284ms)1301=== NAME TestClientSharedPathCommittedMidPush1302 client_integration_test.go:680: Retrieved narinfo from S3:1303 StorePath: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientSharedPathCommittedMidPush3676713933/001/store/9wqqqsl3d8y950zndqn5l15vwj3xvwk4-shared-dep1304 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1305 Compression: zstd1306 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821307 NarSize: 1361308 References: 1309 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1310 client_integration_test.go:680: Retrieved narinfo from S3:1311 StorePath: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientSharedPathCommittedMidPush3676713933/001/store/bjvw1jb5q3ds4bq3hnsq2i8khyq1gnba-top1312 URL: nar/0b19yfmym4rj71w4y41r32gswgiigy5xbnykvzvqk8lbwb9rr3lx.nar.zst1313 Compression: zstd1314 NarHash: sha256:0b19yfmym4rj71w4y41r32gswgiigy5xbnykvzvqk8lbwb9rr3lx1315 NarSize: 2801316 References: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientSharedPathCommittedMidPush3676713933/001/store/9wqqqsl3d8y950zndqn5l15vwj3xvwk4-shared-dep1317 CA: text:sha256:17fi03hic5arzj3s6yi8h6i4szlr5xc1ydw974xswccinhxifv4n1318=== NAME TestOrphanedObjectsGCStressTest1319 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1320--- PASS: TestGCBugBareHashReferences (8.05s)1321=== CONT TestGCSweepSkipsPendingObjects13222026/10/07 06:18:50 INFO lead: acquired remote=192.0.2.1:12341323=== NAME TestOrphanedObjectsGCStressTest1324 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1325--- PASS: TestClientSharedPathCommittedMidPush (8.41s)1326=== CONT TestGCSweepDeliversEachKeyOnce13272026/10/07 06:18:51 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld5 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1328--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (7.84s)1329=== CONT TestClientIntegration13302026/10/07 06:18:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13312026/10/07 06:18:51 INFO Received uploads request method=POST path=/api/pending_closures13322026/10/07 06:18:51 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ODE2OTUzMjQtMzU0ZS00NDlmLWJkNjMtNWRlODFjNzk5YTVlLjFkZTFkNGQ3LTE1OGItNGVlMy05ZjRkLWY2MzM4ZDc4NGRiOXgxNzkxMzUzOTI5NDE0Mjg5MDAw parts=1213332026/10/07 06:18:51 INFO Received uploads request method=POST path=/api/pending_closures13342026/10/07 06:18:51 INFO Received uploads request method=POST path=/api/pending_closures13352026/10/07 06:18:52 INFO lead: acquired remote=192.0.2.1:123413362026/10/07 06:18:52 INFO lead: released remote=192.0.2.1:12341337--- PASS: TestLeadIncumbentAnnouncesAtOnce (7.43s)1338=== CONT TestClientWithDependencies13392026/10/07 06:18:52 INFO lead: released remote=192.0.2.1:12341340--- PASS: TestLeadEndsOnShutdown (8.53s)1341=== CONT TestClientMultipleUploads13422026/10/07 06:18:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13432026/10/07 06:18:52 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ODE2OTUzMjQtMzU0ZS00NDlmLWJkNjMtNWRlODFjNzk5YTVlLjI3ZDc3NzY5LTgxM2QtNGRmYS05YTdjLTg4NDdhZWMzNTFhZHgxNzkxMzUzOTMxNzA1MjgxMDAw13442026/10/07 06:18:52 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ODE2OTUzMjQtMzU0ZS00NDlmLWJkNjMtNWRlODFjNzk5YTVlLjI3ZDc3NzY5LTgxM2QtNGRmYS05YTdjLTg4NDdhZWMzNTFhZHgxNzkxMzUzOTMxNzA1MjgxMDAw parts=11345--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (7.65s)1346=== CONT TestCacheConfigHandler1347=== RUN TestCacheConfigHandler/full_config,_no_issuer1348=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1349=== RUN TestCacheConfigHandler/no_cache_url_configured1350=== PAUSE TestCacheConfigHandler/no_cache_url_configured1351=== RUN TestCacheConfigHandler/no_signing_keys1352=== PAUSE TestCacheConfigHandler/no_signing_keys1353=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1354=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1355=== CONT TestClientCADerivations1356=== RUN TestPush_RejectsBadRequests/no_objects1357=== PAUSE TestPush_RejectsBadRequests/no_objects1358=== RUN TestPush_RejectsBadRequests/bad_root1359=== PAUSE TestPush_RejectsBadRequests/bad_root1360=== RUN TestPush_RejectsBadRequests/root_not_in_objects1361=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1362=== RUN TestPush_RejectsBadRequests/no_roots1363=== PAUSE TestPush_RejectsBadRequests/no_roots1364=== CONT TestClientErrorHandling1365=== RUN TestClientErrorHandling/InvalidStorePath1366=== PAUSE TestClientErrorHandling/InvalidStorePath1367=== RUN TestClientErrorHandling/InvalidAuthToken1368=== PAUSE TestClientErrorHandling/InvalidAuthToken1369=== RUN TestClientErrorHandling/ServerNotAvailable1370=== PAUSE TestClientErrorHandling/ServerNotAvailable1371=== CONT TestCacheStatsHandler13722026/10/07 06:18:52 INFO lead: acquired remote=192.0.2.1:12341373--- PASS: TestReadRedirectUsesPublicS3URL (7.75s)1374=== CONT TestService_AuthMiddleware_OIDC13752026/10/07 06:18:53 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53398/oidc13762026/10/07 06:18:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13772026/10/07 06:18:53 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ODE2OTUzMjQtMzU0ZS00NDlmLWJkNjMtNWRlODFjNzk5YTVlLjg3YzY4MjcxLTQxMjgtNGRjMC05ZjAzLWRkOWQ1N2Y0ZjdmZngxNzkxMzUzOTMxNzM3MjMzMDAw error="Get \"http://127.0.0.1:1/bucket56/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"13782026/10/07 06:18:53 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ODE2OTUzMjQtMzU0ZS00NDlmLWJkNjMtNWRlODFjNzk5YTVlLjhkYzA2YmQzLWRlMDQtNGQxYy1iNTZkLWUzZDliMjgwMGE4NHgxNzkxMzUzOTMxNjc5NzI5MDAw parts=1213792026/10/07 06:18:53 INFO Received cleanup request method=DELETE path=/api/pending_closures13802026/10/07 06:18:53 INFO Aborted multipart uploads count=1 kept=013812026/10/07 06:18:53 INFO lead: released remote=192.0.2.1:12341382--- PASS: TestRedundantMultipartUpload (11.57s)1383=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13842026/10/07 06:18:54 INFO lead: acquired remote=192.0.2.1:123413852026/10/07 06:18:54 INFO Received push request method=POST path=/api/pushes1386--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (8.33s)1387=== CONT TestService_ReadScope_PublicByDefault1388--- PASS: TestConnectWaitsForAPeerMigration (8.93s)1389=== CONT TestService_ReadAuthMiddleware13902026/10/07 06:18:54 INFO Received uploads request method=POST path=/api/pending_closures13912026/10/07 06:18:54 INFO Received uploads request method=POST path=/api/pending_closures13922026/10/07 06:18:54 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13932026/10/07 06:18:54 INFO Uploading xq5sxxx5clb6xndc9c5h449mvc9kdak0-shared-dep (136B)13942026/10/07 06:18:54 INFO Uploading s7aq8l1mssb5yz9mn3rcnzyx6ixhm81l-b (272B)13952026/10/07 06:18:54 WARN Failed to register uploaded object key=xq5sxxx5clb6xndc9c5h449mvc9kdak0.ls error="server returned 404: 404 page not found\n"13962026/10/07 06:18:54 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13972026/10/07 06:18:54 WARN Failed to register uploaded object key=b60zg5jv4bfxgnhb4pl6scms9a9b74vk.ls error="server returned 404: 404 page not found\n"13982026/10/07 06:18:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13992026/10/07 06:18:54 WARN Failed to register uploaded object key=s7aq8l1mssb5yz9mn3rcnzyx6ixhm81l.ls error="server returned 404: 404 page not found\n"14002026/10/07 06:18:54 WARN Failed to register uploaded object key=nar/1a2by6khbgiszdgj3qy6sb0zr8rnra2ccqi3ldz6wq7fb1grrxr0.nar.zst error="server returned 404: 404 page not found\n"14012026/10/07 06:18:54 INFO Signed narinfos id=2 count=214022026/10/07 06:18:54 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14032026/10/07 06:18:54 INFO Signed narinfos id=1 count=214042026/10/07 06:18:54 INFO Uploading 4 narinfos14052026/10/07 06:18:54 WARN Failed to register uploaded object key=s7aq8l1mssb5yz9mn3rcnzyx6ixhm81l.narinfo error="server returned 404: 404 page not found\n"14062026/10/07 06:18:54 WARN Failed to register uploaded object key=xq5sxxx5clb6xndc9c5h449mvc9kdak0.narinfo error="server returned 404: 404 page not found\n"14072026/10/07 06:18:54 WARN Failed to register uploaded object key=b60zg5jv4bfxgnhb4pl6scms9a9b74vk.narinfo error="server returned 404: 404 page not found\n"14082026/10/07 06:18:54 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14092026/10/07 06:18:54 WARN Failed to register uploaded object key=xq5sxxx5clb6xndc9c5h449mvc9kdak0.narinfo error="server returned 404: 404 page not found\n"14102026/10/07 06:18:54 INFO Completed upload id=2 objects=6 duration=53.18125ms14112026/10/07 06:18:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14122026/10/07 06:18:54 INFO Completed upload id=1 objects=6 duration=1.246375ms14132026/10/07 06:18:54 INFO Upload complete. (395ms)1414=== NAME TestClientFallsBackToClosures1415 client_pushes_test.go:112: Retrieved narinfo from S3:1416 StorePath: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientFallsBackToClosures3618563662/001/store/xq5sxxx5clb6xndc9c5h449mvc9kdak0-shared-dep1417 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1418 Compression: zstd1419 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821420 NarSize: 1361421 References: 1422 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1423 client_pushes_test.go:112: Retrieved narinfo from S3:1424 StorePath: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientFallsBackToClosures3618563662/001/store/b60zg5jv4bfxgnhb4pl6scms9a9b74vk-a1425 URL: nar/1a2by6khbgiszdgj3qy6sb0zr8rnra2ccqi3ldz6wq7fb1grrxr0.nar.zst1426 Compression: zstd1427 NarHash: sha256:1a2by6khbgiszdgj3qy6sb0zr8rnra2ccqi3ldz6wq7fb1grrxr01428 NarSize: 2721429 References: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientFallsBackToClosures3618563662/001/store/xq5sxxx5clb6xndc9c5h449mvc9kdak0-shared-dep1430 CA: text:sha256:0xidf0nfdl78vpzi8r8d347r4i1dcqdxqy28zgwfjpfz7fnlz1fx1431 client_pushes_test.go:112: Retrieved narinfo from S3:1432 StorePath: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientFallsBackToClosures3618563662/001/store/s7aq8l1mssb5yz9mn3rcnzyx6ixhm81l-b1433 URL: nar/1a2by6khbgiszdgj3qy6sb0zr8rnra2ccqi3ldz6wq7fb1grrxr0.nar.zst1434 Compression: zstd1435 NarHash: sha256:1a2by6khbgiszdgj3qy6sb0zr8rnra2ccqi3ldz6wq7fb1grrxr01436 NarSize: 2721437 References: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientFallsBackToClosures3618563662/001/store/xq5sxxx5clb6xndc9c5h449mvc9kdak0-shared-dep1438 CA: text:sha256:0xidf0nfdl78vpzi8r8d347r4i1dcqdxqy28zgwfjpfz7fnlz1fx1439--- PASS: TestClientFallsBackToClosures (8.93s)1440=== CONT TestService_RequireScope_OIDC14412026/10/07 06:18:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53431/oidc14422026/10/07 06:18:55 INFO lead: released remote=192.0.2.1:12341443--- PASS: TestLeadElectsOneAndHandsOver (9.94s)1444=== CONT TestService_AuthMiddleware_MTLSProxyHeader14452026/10/07 06:18:55 INFO Received push request method=POST path=/api/pushes14462026/10/07 06:18:55 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14472026/10/07 06:18:55 INFO Uploading b1vz0842wsc7116l7dihy620d815ilip-a (264B)14482026/10/07 06:18:55 INFO Uploading k3iyw8fs52c7lkja54byr3rd3rwmxpfp-shared-dep (136B)14492026/10/07 06:18:55 WARN Failed to register uploaded object key=k3iyw8fs52c7lkja54byr3rd3rwmxpfp.ls error="server returned 404: 404 page not found\n"14502026/10/07 06:18:55 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14512026/10/07 06:18:55 WARN Failed to register uploaded object key=b1vz0842wsc7116l7dihy620d815ilip.ls error="server returned 404: 404 page not found\n"14522026/10/07 06:18:55 WARN Failed to register uploaded object key=vhbfzsly0kz9wa73w3hfc1lwnagj5yhl.ls error="server returned 404: 404 page not found\n"14532026/10/07 06:18:55 WARN Failed to register uploaded object key=nar/0qn516lxfd9c1dwd63vqsbllkwgwzs8mz4dvwgvxdmcgwh91dd7i.nar.zst error="server returned 404: 404 page not found\n"14542026/10/07 06:18:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14552026/10/07 06:18:55 INFO Signed narinfos id=1 count=314562026/10/07 06:18:55 INFO Uploading 3 narinfos1457=== NAME TestPinProtectsFromGC1458 client_integration_test.go:731: Pinned store path: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestPinProtectsFromGC1417370928/001/store/4i3gn5by9j0yia5j492wq2sz4pp92q9j-pinned-file.txt1459 client_integration_test.go:732: Unpinned store path: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestPinProtectsFromGC1417370928/001/store/g3y45qv453nqdx0wghplspa4iqb93qil-unpinned-file.txt14602026/10/07 06:18:55 WARN Failed to register uploaded object key=b1vz0842wsc7116l7dihy620d815ilip.narinfo error="server returned 404: 404 page not found\n"14612026/10/07 06:18:55 WARN Failed to register uploaded object key=k3iyw8fs52c7lkja54byr3rd3rwmxpfp.narinfo error="server returned 404: 404 page not found\n"14622026/10/07 06:18:55 INFO Received complete push request method=POST path=/api/pushes/1/complete14632026/10/07 06:18:55 WARN Failed to register uploaded object key=vhbfzsly0kz9wa73w3hfc1lwnagj5yhl.narinfo error="server returned 404: 404 page not found\n"14642026/10/07 06:18:55 INFO Completed push id=1 objects=8 duration=59.460791ms14652026/10/07 06:18:55 INFO Upload complete. (331ms)1466=== NAME TestClientPushesUseOnePush1467 client_pushes_test.go:97: Retrieved narinfo from S3:1468 StorePath: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientPushesUseOnePush2458594106/001/store/k3iyw8fs52c7lkja54byr3rd3rwmxpfp-shared-dep1469 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1470 Compression: zstd1471 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821472 NarSize: 1361473 References: 1474 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1475 client_pushes_test.go:97: Retrieved narinfo from S3:1476 StorePath: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientPushesUseOnePush2458594106/001/store/b1vz0842wsc7116l7dihy620d815ilip-a1477 URL: nar/0qn516lxfd9c1dwd63vqsbllkwgwzs8mz4dvwgvxdmcgwh91dd7i.nar.zst1478 Compression: zstd1479 NarHash: sha256:0qn516lxfd9c1dwd63vqsbllkwgwzs8mz4dvwgvxdmcgwh91dd7i1480 NarSize: 2641481 References: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientPushesUseOnePush2458594106/001/store/k3iyw8fs52c7lkja54byr3rd3rwmxpfp-shared-dep1482 CA: text:sha256:1rfddcf7sm7bp0v1m02ari204jw0krxmbsgzb3vz88wlhs5w63101483 client_pushes_test.go:97: Retrieved narinfo from S3:1484 StorePath: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientPushesUseOnePush2458594106/001/store/vhbfzsly0kz9wa73w3hfc1lwnagj5yhl-b1485 URL: nar/0qn516lxfd9c1dwd63vqsbllkwgwzs8mz4dvwgvxdmcgwh91dd7i.nar.zst1486 Compression: zstd1487 NarHash: sha256:0qn516lxfd9c1dwd63vqsbllkwgwzs8mz4dvwgvxdmcgwh91dd7i1488 NarSize: 2641489 References: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientPushesUseOnePush2458594106/001/store/k3iyw8fs52c7lkja54byr3rd3rwmxpfp-shared-dep1490 CA: text:sha256:1rfddcf7sm7bp0v1m02ari204jw0krxmbsgzb3vz88wlhs5w631014912026/10/07 06:18:55 INFO Received push request method=POST path=/api/pushes1492--- PASS: TestClientPushesUseOnePush (8.76s)1493=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale14942026/10/07 06:18:55 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14952026/10/07 06:18:55 INFO Uploading 4i3gn5by9j0yia5j492wq2sz4pp92q9j-pinned-file.txt (128B)14962026/10/07 06:18:55 INFO Received uploads request method=POST path=/api/pending_closures14972026/10/07 06:18:55 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14982026/10/07 06:18:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14992026/10/07 06:18:55 WARN Failed to register uploaded object key=4i3gn5by9j0yia5j492wq2sz4pp92q9j.ls error="server returned 404: 404 page not found\n"15002026/10/07 06:18:55 INFO Signed narinfos id=1 count=115012026/10/07 06:18:55 INFO Uploading 1 narinfos15022026/10/07 06:18:55 INFO Received complete push request method=POST path=/api/pushes/1/complete15032026/10/07 06:18:55 WARN Failed to register uploaded object key=4i3gn5by9j0yia5j492wq2sz4pp92q9j.narinfo error="server returned 404: 404 page not found\n"15042026/10/07 06:18:55 INFO Completed push id=1 objects=3 duration=28.831084ms15052026/10/07 06:18:55 INFO Upload complete. (419ms)1506=== NAME TestOrphanedObjectsGCStressTest1507 orphaned_objects_gc_test.go:503: Stress test completed successfully:1508 orphaned_objects_gc_test.go:504: - Active objects preserved: 201509 orphaned_objects_gc_test.go:505: - Objects deleted: 2101510 orphaned_objects_gc_test.go:506: - Total GC'd: 2101511--- PASS: TestOrphanedObjectsGCStressTest (19.93s)1512=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh15132026/10/07 06:18:56 INFO Received push request method=POST path=/api/pushes1514--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (8.48s)15152026/10/07 06:18:56 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15162026/10/07 06:18:56 INFO Uploading g3y45qv453nqdx0wghplspa4iqb93qil-unpinned-file.txt (128B)1517=== CONT TestIsValidCachePath/narinfo1518=== CONT TestIsValidCachePath/traversal_parent1519=== CONT TestIsValidCachePath/short_hash1520=== CONT TestIsValidCachePath/wrong_extension1521=== CONT TestIsValidCachePath/leading_slash1522=== CONT TestIsValidCachePath/empty1523=== CONT TestIsValidCachePath/random_path1524=== CONT TestIsValidCachePath/invalid_char_u1525=== CONT TestIsValidCachePath/invalid_char_e1526=== CONT TestIsValidCachePath/traversal_in_middle1527=== CONT TestIsValidCachePath/ls1528=== CONT TestIsValidCachePath/index.html1529=== CONT TestIsValidCachePath/nix-cache-info1530=== CONT TestIsValidCachePath/realisation1531=== CONT TestIsValidCachePath/log1532=== CONT TestIsValidCachePath/nar_xz1533=== CONT TestIsValidCachePath/nar_uncompressed1534=== CONT TestIsValidCachePath/nar_bz21535=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1536=== CONT TestIsValidCachePath/nar_zst1537--- PASS: TestIsValidCachePath (0.00s)1538 --- PASS: TestIsValidCachePath/narinfo (0.00s)1539 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1540 --- PASS: TestIsValidCachePath/short_hash (0.00s)1541 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1542 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1543 --- PASS: TestIsValidCachePath/empty (0.00s)1544 --- PASS: TestIsValidCachePath/random_path (0.00s)1545 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1546 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1547 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1548 --- PASS: TestIsValidCachePath/ls (0.00s)1549 --- PASS: TestIsValidCachePath/index.html (0.00s)1550 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1551 --- PASS: TestIsValidCachePath/realisation (0.00s)1552 --- PASS: TestIsValidCachePath/log (0.00s)1553 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1554 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1555 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1556 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1557 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1558=== CONT TestServerTLSConfig/no_client_CA1559=== CONT TestServerTLSConfig/not_a_PEM_file15602026/10/07 06:18:56 WARN Failed to register uploaded object key=g3y45qv453nqdx0wghplspa4iqb93qil.ls error="server returned 404: 404 page not found\n"15612026/10/07 06:18:56 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15622026/10/07 06:18:56 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"1563=== CONT TestParseSingleRange/none15642026/10/07 06:18:56 INFO Signed narinfos id=2 count=11565=== CONT TestParseSingleRange/open-ended1566=== CONT TestParseSingleRange/closed1567=== CONT TestParseSingleRange/malformed_end_before_start1568=== CONT TestParseSingleRange/malformed_both_empty1569=== CONT TestParseSingleRange/malformed_no_dash1570=== CONT TestParseSingleRange/multi-range_ignored1571=== CONT TestParseSingleRange/unknown_unit1572=== CONT TestParseSingleRange/start_past_EOF1573=== CONT TestServerTLSConfig/missing_CA_file15742026/10/07 06:18:56 INFO Uploading 1 narinfos1575--- PASS: TestServerTLSConfig (0.00s)1576 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1577 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)1578 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1579=== CONT TestParseSingleRange/start_far_past_EOF1580=== CONT TestParseSingleRange/suffix_exceeds_size1581=== CONT TestParseSingleRange/single_byte1582=== CONT TestParseSingleRange/suffix1583=== CONT TestParseSingleRange/end_clamped_to_size1584--- PASS: TestParseSingleRange (0.00s)1585 --- PASS: TestParseSingleRange/none (0.00s)1586 --- PASS: TestParseSingleRange/open-ended (0.00s)1587 --- PASS: TestParseSingleRange/closed (0.00s)1588 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1589 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1590 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1591 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1592 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1593 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1594 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1595 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1596 --- PASS: TestParseSingleRange/single_byte (0.00s)1597 --- PASS: TestParseSingleRange/suffix (0.00s)1598 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1599=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16002026/10/07 06:18:56 INFO Received request for more parts method=POST path=/1601=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16022026/10/07 06:18:56 INFO Received complete multipart upload request method=POST path=/16032026/10/07 06:18:56 INFO Received complete push request method=POST path=/api/pushes/2/complete16042026/10/07 06:18:56 WARN Failed to register uploaded object key=g3y45qv453nqdx0wghplspa4iqb93qil.narinfo error="server returned 404: 404 page not found\n"1605=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16062026/10/07 06:18:56 INFO Received uploads request method=POST path=/16072026/10/07 06:18:56 INFO Completed push id=2 objects=3 duration=57.852292ms16082026/10/07 06:18:56 INFO Upload complete. (268ms)1609--- PASS: TestObjectStatsLargeCommit (19.75s)1610=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16112026/10/07 06:18:56 INFO Received uploads request method=POST path=/1612=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16132026/10/07 06:18:56 INFO Received complete multipart upload request method=POST path=/1614=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16152026/10/07 06:18:56 INFO Received request for more parts method=POST path=/1616=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16172026/10/07 06:18:56 INFO Received uploads request method=POST path=/1618--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1619 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1620 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1621 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1622 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1623=== CONT TestIsValidUploadKey/narinfo1624=== CONT TestIsValidUploadKey/realisation_plus_in_output1625=== CONT TestIsValidUploadKey/unknown_type1626=== CONT TestIsValidUploadKey/empty_key1627=== CONT TestIsValidUploadKey/absolute1628=== CONT TestIsValidUploadKey/traversal_nar1629=== CONT TestIsValidUploadKey/traversal1630=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1631=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1632=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1633=== CONT TestIsValidUploadKey/index.html1634=== CONT TestIsValidUploadKey/nix-cache-info1635=== CONT TestIsValidUploadKey/build_log_home-manager_file1636=== CONT TestIsValidUploadKey/realisation1637=== CONT TestIsValidUploadKey/build_log_equals1638=== CONT TestIsValidUploadKey/build_log_question_mark1639=== CONT TestIsValidUploadKey/build_log_plus_in_name1640=== CONT TestIsValidUploadKey/nar_plain1641=== CONT TestIsValidUploadKey/build_log1642=== CONT TestIsValidUploadKey/listing1643=== CONT TestIsValidUploadKey/nar_xz1644=== CONT TestIsValidUploadKey/nar_zst1645--- PASS: TestIsValidUploadKey (0.01s)1646 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1647 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1648 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1649 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1650 --- PASS: TestIsValidUploadKey/absolute (0.00s)1651 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1652 --- PASS: TestIsValidUploadKey/traversal (0.00s)1653 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1654 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1655 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1656 --- PASS: TestIsValidUploadKey/index.html (0.00s)1657 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1658 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1659 --- PASS: TestIsValidUploadKey/realisation (0.00s)1660 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1661 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1662 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1663 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1664 --- PASS: TestIsValidUploadKey/build_log (0.00s)1665 --- PASS: TestIsValidUploadKey/listing (0.00s)1666 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1667 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1668=== CONT TestPendingClosureWriteTimeout/empty1669=== CONT TestPendingClosureWriteTimeout/670k_objects1670=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline16712026/10/07 06:18:56 INFO Starting cleanup of old closures method=DELETE path=/api/closures16722026/10/07 06:18:56 INFO Garbage collection started16732026/10/07 06:18:56 INFO Aborted multipart uploads count=0 kept=016742026/10/07 06:18:56 WARN Force mode enabled - objects will be deleted immediately without grace period16752026/10/07 06:18:56 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=016762026/10/07 06:18:56 INFO Vacuumed table table=pending_closures16772026/10/07 06:18:56 INFO Vacuumed table table=pending_objects16782026/10/07 06:18:56 INFO Vacuumed table table=multipart_uploads16792026/10/07 06:18:56 INFO Vacuumed table table=closures16802026/10/07 06:18:56 INFO Vacuumed table table=objects1681=== CONT TestPendingClosureWriteTimeout/400_objects1682=== CONT TestProxyWriteTimeout/narinfo1683--- PASS: TestUploadHandlersRejectOversizedBody (0.04s)1684 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.03s)1685 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)1686 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.49s)1687=== CONT TestProxyWriteTimeout/10_GiB_nar1688=== CONT TestProxyWriteTimeout/unknown_size1689=== CONT TestProxyWriteTimeout/1_GiB_nar1690=== CONT TestGCEndsOnShutdown/before_the_run1691--- PASS: TestProxyWriteTimeout (0.00s)1692 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1693 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1694 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1695 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)16962026/10/07 06:18:56 INFO Aborted multipart uploads count=0 kept=016972026/10/07 06:18:56 WARN Force mode enabled - objects will be deleted immediately without grace period16982026/10/07 06:18:56 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=016992026/10/07 06:18:56 INFO Vacuumed table table=pending_closures17002026/10/07 06:18:56 INFO Vacuumed table table=pending_objects17012026/10/07 06:18:56 INFO Vacuumed table table=multipart_uploads17022026/10/07 06:18:56 INFO Vacuumed table table=closures17032026/10/07 06:18:56 INFO Vacuumed table table=objects17042026/10/07 06:18:56 INFO Aborted multipart uploads count=0 kept=017052026/10/07 06:18:56 WARN Force mode enabled - objects will be deleted immediately without grace period17062026/10/07 06:18:56 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=017072026/10/07 06:18:56 INFO Vacuumed table table=pending_closures17082026/10/07 06:18:56 INFO Vacuumed table table=pending_objects17092026/10/07 06:18:56 INFO Vacuumed table table=multipart_uploads17102026/10/07 06:18:56 INFO Vacuumed table table=closures17112026/10/07 06:18:56 INFO Vacuumed table table=objects1712--- PASS: TestSweepSkipsRowsLockedByPush (8.10s)1713=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1714--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (9.67s)1715=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1716--- PASS: TestReadProxyRangeRequest (7.84s)1717=== CONT TestResolveDBConnectionString/flag_wins1718=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1719=== CONT TestResolveDBConnectionString/nothing_configured1720=== CONT TestResolveDBConnectionString/missing_file_is_an_error1721=== CONT TestResolveDBConnectionString/file_when_flag_empty1722=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1723--- PASS: TestResolveDBConnectionString (0.03s)1724 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1725 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1726 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1727 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1728 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)17292026/10/07 06:18:57 INFO Received uploads request method=POST path=/api/pending_closures17302026/10/07 06:18:57 INFO Aborted multipart uploads count=0 kept=017312026/10/07 06:18:57 WARN Force mode enabled - objects will be deleted immediately without grace period17322026/10/07 06:18:57 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."17332026/10/07 06:18:57 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1734--- PASS: TestFailedS3DeleteKeepsTombstone (7.32s)1735=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check17362026/10/07 06:18:57 INFO Received uploads request method=POST path=/api/pending_closures1737--- PASS: TestTombstonedObjectOfferedWithoutWaiting (7.19s)1738=== CONT TestCacheConfigHandler/full_config,_no_issuer1739=== CONT TestCacheConfigHandler/no_signing_keys1740=== CONT TestCacheConfigHandler/no_cache_url_configured1741=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1742--- PASS: TestCacheConfigHandler (0.00s)1743 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1744 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1745 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1746 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1747=== CONT TestPush_RejectsBadRequests/no_objects17482026/10/07 06:18:57 INFO Received push request method=POST path=/api/pushes1749=== CONT TestClientErrorHandling/InvalidStorePath17502026/10/07 06:18:58 INFO Received uploads request method=POST path=/api/pending_closures17512026/10/07 06:18:58 INFO Aborted multipart uploads count=0 kept=017522026/10/07 06:18:58 WARN Force mode enabled - objects will be deleted immediately without grace period17532026/10/07 06:18:58 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=017542026/10/07 06:18:58 INFO Vacuumed table table=pending_closures17552026/10/07 06:18:58 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=017562026/10/07 06:18:58 INFO Vacuumed table table=pending_objects17572026/10/07 06:18:58 INFO Vacuumed table table=multipart_uploads17582026/10/07 06:18:58 INFO Received create pin request method=POST path=/api/pins/myapp17592026/10/07 06:18:58 INFO Vacuumed table table=closures17602026/10/07 06:18:58 INFO Vacuumed table table=objects17612026/10/07 06:18:58 INFO Created/updated pin name=myapp store_path=/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestPinProtectsFromGC1417370928/001/store/4i3gn5by9j0yia5j492wq2sz4pp92q9j-pinned-file.txt narinfo_key=4i3gn5by9j0yia5j492wq2sz4pp92q9j.narinfo17622026/10/07 06:18:58 INFO Starting cleanup of old closures method=DELETE path=/api/closures17632026/10/07 06:18:58 INFO Garbage collection started17642026/10/07 06:18:58 INFO Aborted multipart uploads count=0 kept=017652026/10/07 06:18:58 WARN Force mode enabled - objects will be deleted immediately without grace period17662026/10/07 06:18:58 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=01767--- PASS: TestGCSweepSkipsPendingObjects (7.45s)1768=== CONT TestPush_RejectsBadRequests/no_roots17692026/10/07 06:18:58 INFO Received push request method=POST path=/api/pushes17702026/10/07 06:18:58 INFO Vacuumed table table=pending_closures1771=== CONT TestPush_RejectsBadRequests/root_not_in_objects17722026/10/07 06:18:58 INFO Received push request method=POST path=/api/pushes1773=== CONT TestPush_RejectsBadRequests/bad_root17742026/10/07 06:18:58 INFO Received push request method=POST path=/api/pushes1775=== CONT TestClientErrorHandling/ServerNotAvailable1776--- PASS: TestPush_RejectsBadRequests (7.69s)1777 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1778 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1779 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1780 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)17812026/10/07 06:18:58 INFO Vacuumed table table=pending_objects17822026/10/07 06:18:58 INFO Vacuumed table table=multipart_uploads17832026/10/07 06:18:58 INFO Vacuumed table table=closures17842026/10/07 06:18:58 INFO Vacuumed table table=objects17852026/10/07 06:18:58 INFO Aborted multipart uploads count=0 kept=017862026/10/07 06:18:58 WARN Force mode enabled - objects will be deleted immediately without grace period17872026/10/07 06:18:58 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=017882026/10/07 06:18:58 INFO Vacuumed table table=pending_closures17892026/10/07 06:18:58 INFO Vacuumed table table=pending_objects17902026/10/07 06:18:58 INFO Vacuumed table table=multipart_uploads17912026/10/07 06:18:58 INFO Vacuumed table table=closures17922026/10/07 06:18:58 INFO Vacuumed table table=objects1793--- PASS: TestGCSweepDeliversEachKeyOnce (7.84s)1794=== CONT TestClientErrorHandling/InvalidAuthToken17952026/10/07 06:18:58 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present17962026/10/07 06:18:59 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=189.218501ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1797=== NAME TestClientIntegration1798 client_integration_test.go:286: Created store path: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientIntegration334296303/002/store/4qvcbqk9sjy9mjqpmnrdqzx3rk83vhcx-test-file.txt17992026/10/07 06:18:59 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=380.277567ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18002026/10/07 06:18:59 INFO Received push request method=POST path=/api/pushes18012026/10/07 06:18:59 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18022026/10/07 06:18:59 INFO Uploading 4qvcbqk9sjy9mjqpmnrdqzx3rk83vhcx-test-file.txt (152B)18032026/10/07 06:18:59 WARN Failed to register uploaded object key=4qvcbqk9sjy9mjqpmnrdqzx3rk83vhcx.ls error="server returned 404: 404 page not found\n"18042026/10/07 06:18:59 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18052026/10/07 06:18:59 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18062026/10/07 06:18:59 INFO Signed narinfos id=1 count=118072026/10/07 06:18:59 INFO Uploading 1 narinfos18082026/10/07 06:18:59 INFO Received complete push request method=POST path=/api/pushes/1/complete18092026/10/07 06:18:59 WARN Failed to register uploaded object key=4qvcbqk9sjy9mjqpmnrdqzx3rk83vhcx.narinfo error="server returned 404: 404 page not found\n"18102026/10/07 06:18:59 INFO Completed push id=1 objects=3 duration=43.594042ms18112026/10/07 06:18:59 INFO Upload complete. (298ms)1812=== NAME TestClientMultipleUploads1813 client_integration_test.go:358: Created store path 0: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientMultipleUploads3224584810/001/store/87llwficwxrhk4kjr08dp1yylmwg8f3w-test-file-0.txt18142026/10/07 06:18:59 INFO All 1 paths already cached1815=== NAME TestClientIntegration1816 client_integration_test.go:312: Retrieved narinfo from S3:1817 StorePath: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientIntegration334296303/002/store/4qvcbqk9sjy9mjqpmnrdqzx3rk83vhcx-test-file.txt1818 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1819 Compression: zstd1820 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11821 NarSize: 1521822 References: 1823 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk118242026/10/07 06:18:59 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=865.736336ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1825 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1826 client_integration_test.go:313: Decompressed .ls content (64 bytes):1827 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1828 client_integration_test.go:316: Testing garbage collection...18292026/10/07 06:18:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures18302026/10/07 06:18:59 INFO Garbage collection started18312026/10/07 06:18:59 INFO Aborted multipart uploads count=0 kept=01832=== NAME TestClientMultipleUploads1833 client_integration_test.go:358: Created store path 1: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientMultipleUploads3224584810/001/store/5lwhilmpg3a6n2acw162nwzvcfah6hkl-test-file-1.txt18342026/10/07 06:18:59 WARN Force mode enabled - objects will be deleted immediately without grace period18352026/10/07 06:18:59 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=018362026/10/07 06:18:59 INFO Vacuumed table table=pending_closures1837 client_integration_test.go:358: Created store path 2: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientMultipleUploads3224584810/001/store/v0pn8vbm3ynqrvb0s6j5lkv7h62v378z-test-file-2.txt18382026/10/07 06:18:59 INFO Vacuumed table table=pending_objects18392026/10/07 06:18:59 INFO Vacuumed table table=multipart_uploads18402026/10/07 06:18:59 INFO Vacuumed table table=closures18412026/10/07 06:19:00 INFO Vacuumed table table=objects18422026/10/07 06:19:00 INFO Received push request method=POST path=/api/pushes18432026/10/07 06:19:00 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18442026/10/07 06:19:00 INFO Uploading 87llwficwxrhk4kjr08dp1yylmwg8f3w-test-file-0.txt (160B)18452026/10/07 06:19:00 INFO Uploading 5lwhilmpg3a6n2acw162nwzvcfah6hkl-test-file-1.txt (160B)18462026/10/07 06:19:00 INFO Uploading v0pn8vbm3ynqrvb0s6j5lkv7h62v378z-test-file-2.txt (160B)18472026/10/07 06:19:00 WARN Failed to register uploaded object key=87llwficwxrhk4kjr08dp1yylmwg8f3w.ls error="server returned 404: 404 page not found\n"18482026/10/07 06:19:00 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18492026/10/07 06:19:00 WARN Failed to register uploaded object key=v0pn8vbm3ynqrvb0s6j5lkv7h62v378z.ls error="server returned 404: 404 page not found\n"18502026/10/07 06:19:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18512026/10/07 06:19:00 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18522026/10/07 06:19:00 WARN Failed to register uploaded object key=5lwhilmpg3a6n2acw162nwzvcfah6hkl.ls error="server returned 404: 404 page not found\n"18532026/10/07 06:19:00 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18542026/10/07 06:19:00 INFO Signed narinfos id=1 count=318552026/10/07 06:19:00 INFO Uploading 3 narinfos18562026/10/07 06:19:00 WARN Failed to register uploaded object key=v0pn8vbm3ynqrvb0s6j5lkv7h62v378z.narinfo error="server returned 404: 404 page not found\n"18572026/10/07 06:19:00 WARN Failed to register uploaded object key=5lwhilmpg3a6n2acw162nwzvcfah6hkl.narinfo error="server returned 404: 404 page not found\n"18582026/10/07 06:19:00 INFO Received complete push request method=POST path=/api/pushes/1/complete18592026/10/07 06:19:00 WARN Failed to register uploaded object key=87llwficwxrhk4kjr08dp1yylmwg8f3w.narinfo error="server returned 404: 404 page not found\n"18602026/10/07 06:19:00 INFO Completed push id=1 objects=9 duration=30.801625ms18612026/10/07 06:19:00 INFO Upload complete. (300ms)1862 client_integration_test.go:369: Uploaded 3 paths in 375.139792ms1863=== NAME TestClientCADerivations1864 client_ca_test.go:136: Built CA derivation: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientCADerivations3191065452/001/store/5wlwx8rpyl9az3zl5w12s2q229nvp6q4-ca-test1865=== NAME TestPinProtectsFromGC1866 client_integration_test.go:840: Pin successfully protected closure from garbage collection1867--- PASS: TestClientMultipleUploads (8.40s)1868--- PASS: TestPinProtectsFromGC (13.59s)18692026-10-07 06:19:00.460 UTC [8996] LOG: checkpoint starting: wal1870=== NAME TestClientCADerivations1871 client_ca_test.go:139: Found 1 dependencies (including self)1872--- PASS: TestCacheStatsHandler (8.10s)18732026/10/07 06:19:00 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.610290418s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1874=== NAME TestClientWithDependencies1875 client_integration_test.go:613: Built derivation: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientWithDependencies790663197/001/store/hh5lmjhacm0n7y5qjwnng1pj8vz38iz5-test-script1876=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1877=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1878=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1879=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1880=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1881=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1882=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1883=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1884=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1885=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected18862026/10/07 06:19:00 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]1887=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1888=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1889=== NAME TestClientWithDependencies18902026/10/07 06:19:00 WARN Authentication failed token_preview=eyJhbGciOi...JSBZLySWNQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1891 client_integration_test.go:615: Found 1 dependencies (including self)18922026/10/07 06:19:00 INFO Received push request method=POST path=/api/pushes1893--- PASS: TestService_AuthMiddleware_OIDC (7.43s)1894 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1895 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1896 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1897 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.02s)18982026/10/07 06:19:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18992026/10/07 06:19:00 INFO Uploading 5wlwx8rpyl9az3zl5w12s2q229nvp6q4-ca-test (144B)19002026/10/07 06:19:00 WARN Failed to register uploaded object key=5wlwx8rpyl9az3zl5w12s2q229nvp6q4.ls error="server returned 404: 404 page not found\n"19012026/10/07 06:19:00 WARN Failed to register uploaded object key=log/zvgrrhhpi6i5myxr8da81wqxds3bhhrp-ca-test.drv error="server returned 404: 404 page not found\n"19022026/10/07 06:19:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19032026/10/07 06:19:00 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19042026/10/07 06:19:00 INFO Signed narinfos id=1 count=119052026/10/07 06:19:00 INFO Uploading 1 narinfos19062026/10/07 06:19:00 INFO Received complete push request method=POST path=/api/pushes/1/complete19072026/10/07 06:19:00 WARN Failed to register uploaded object key=5wlwx8rpyl9az3zl5w12s2q229nvp6q4.narinfo error="server returned 404: 404 page not found\n"19082026/10/07 06:19:00 INFO Completed push id=1 objects=4 duration=16.309625ms19092026/10/07 06:19:00 INFO Upload complete. (323ms)19102026/10/07 06:19:00 INFO Received push request method=POST path=/api/pushes1911=== NAME TestClientCADerivations1912 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientCADerivations3191065452/001/store/5wlwx8rpyl9az3zl5w12s2q229nvp6q4-ca-test1913 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1914 Compression: zstd1915 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1916 NarSize: 1441917 References: 1918 Deriver: /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientCADerivations3191065452/001/store/zvgrrhhpi6i5myxr8da81wqxds3bhhrp-ca-test.drv1919 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1920 client_ca_test.go:185: Checking for realisation files in S3...1921 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1922 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache19232026/10/07 06:19:00 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19242026/10/07 06:19:00 INFO Uploading hh5lmjhacm0n7y5qjwnng1pj8vz38iz5-test-script (136B)19252026/10/07 06:19:00 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"19262026/10/07 06:19:00 WARN Failed to register uploaded object key=hh5lmjhacm0n7y5qjwnng1pj8vz38iz5.ls error="server returned 404: 404 page not found\n"19272026/10/07 06:19:00 WARN Failed to register uploaded object key=log/9gmxp2r5y2dbprby5fwr16q999nlis17-test-script.drv error="server returned 404: 404 page not found\n"19282026/10/07 06:19:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19292026/10/07 06:19:00 INFO Signed narinfos id=1 count=119302026/10/07 06:19:00 INFO Uploading 1 narinfos19312026/10/07 06:19:00 INFO Received complete push request method=POST path=/api/pushes/1/complete19322026/10/07 06:19:00 WARN Failed to register uploaded object key=hh5lmjhacm0n7y5qjwnng1pj8vz38iz5.narinfo error="server returned 404: 404 page not found\n"1933--- PASS: TestDeleteClosuresRacingPins (12.76s)19342026/10/07 06:19:00 INFO Completed push id=1 objects=4 duration=10.699459ms19352026/10/07 06:19:00 INFO Upload complete. (184ms)1936=== NAME TestClientWithDependencies1937 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientWithDependencies790663197/001/store) requires matching store prefix19382026/10/07 06:19:00 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19392026/10/07 06:19:00 WARN mTLS auth: bound subjects configured but subject DN unavailable19402026/10/07 06:19:00 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1941--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.96s)1942=== NAME TestClientCADerivations1943 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket82?endpoint=http://localhost:53122®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestClientCADerivations3191065452/001/store'1944 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11945--- PASS: TestClientWithDependencies (9.03s)1946--- PASS: TestClientCADerivations (8.99s)1947--- PASS: TestService_ReadScope_PublicByDefault (6.91s)1948--- PASS: TestService_ReadAuthMiddleware (7.00s)1949=== RUN TestService_RequireScope_OIDC/builder_may_write1950=== PAUSE TestService_RequireScope_OIDC/builder_may_write1951=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1952=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1953=== RUN TestService_RequireScope_OIDC/ops_may_admin1954=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1955=== RUN TestService_RequireScope_OIDC/ops_may_not_write1956=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1957=== RUN TestService_RequireScope_OIDC/reader_may_not_write1958=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1959=== RUN TestService_RequireScope_OIDC/static_token_may_admin1960=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1961=== RUN TestService_RequireScope_OIDC/static_token_may_write1962=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1963=== RUN TestService_RequireScope_OIDC/reader_may_read1964=== PAUSE TestService_RequireScope_OIDC/reader_may_read1965=== RUN TestService_RequireScope_OIDC/writer_implies_read1966=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1967=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1968=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1969=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1970=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1971=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1972=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1973=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1974=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1975=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1976=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1977=== CONT TestService_RequireScope_OIDC/builder_may_write1978=== CONT TestService_RequireScope_OIDC/reader_may_read1979=== CONT TestService_RequireScope_OIDC/reader_may_not_write1980=== CONT TestService_RequireScope_OIDC/static_token_may_write1981=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1982=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1983=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19842026/10/07 06:19:01 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]1985=== CONT TestService_RequireScope_OIDC/ops_may_admin1986=== CONT TestService_RequireScope_OIDC/ops_may_not_write1987=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1988=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1989=== CONT TestService_RequireScope_OIDC/static_token_may_admin1990=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1991=== CONT TestService_RequireScope_OIDC/writer_implies_read1992--- PASS: TestService_RequireScope_OIDC (6.71s)1993 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1994 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1995 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1996 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1997 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1998 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1999 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2000 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2001 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2002 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2003 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2004 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2005 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2006 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)20072026/10/07 06:19:01 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02008=== NAME TestClientIntegration2009 client_integration_test.go:323: Objects in database after GC:2010 client_integration_test.go:323: Successfully deleted all objects with GC --force2011--- PASS: TestClientIntegration (10.52s)2012--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.74s)20132026/10/07 06:19:02 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20142026/10/07 06:19:02 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=190.205271ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20152026/10/07 06:19:02 INFO Received uploads request method=POST path=/api/pending_closures20162026/10/07 06:19:02 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=377.414809ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20172026/10/07 06:19:02 INFO Received uploads request method=POST path=/api/pending_closures20182026/10/07 06:19:02 INFO Aborted multipart uploads count=0 kept=020192026/10/07 06:19:02 WARN Force mode enabled - objects will be deleted immediately without grace period20202026/10/07 06:19:02 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=020212026/10/07 06:19:02 INFO Vacuumed table table=pending_closures20222026/10/07 06:19:02 INFO Vacuumed table table=pending_objects20232026/10/07 06:19:02 INFO Vacuumed table table=multipart_uploads20242026/10/07 06:19:02 INFO Vacuumed table table=closures20252026/10/07 06:19:02 INFO Vacuumed table table=objects2026--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2027 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (6.98s)2028 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (6.80s)20292026/10/07 06:19:02 INFO Aborted multipart uploads count=0 kept=020302026/10/07 06:19:02 WARN Force mode enabled - objects will be deleted immediately without grace period20312026/10/07 06:19:02 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=738.290734ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20322026/10/07 06:19:02 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:53122/bucket96/?delete=\": context canceled"20332026/10/07 06:19:03 INFO Aborted multipart uploads count=0 kept=020342026/10/07 06:19:03 WARN Force mode enabled - objects will be deleted immediately without grace period20352026-10-07 06:19:03.092 UTC [9554] ERROR: canceling statement due to user request20362026-10-07 06:19:03.092 UTC [9554] STATEMENT: -- name: MarkStaleObjects :execrows2037 WITH RECURSIVE ct AS (2038 SELECT timezone('UTC', now()) AS now2039 ),2040 closure_reach AS (2041 -- Start with all closure keys2042 SELECT o.key, o.refs2043 FROM objects o2044 INNER JOIN closures c ON o.key = c.key2045 UNION2046 -- Recursively add all referenced objects2047 SELECT o.key, o.refs2048 FROM objects o2049 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2050 ),2051 reachable_objects AS (2052 SELECT DISTINCT key FROM closure_reach2053 ),2054 stale_objects AS (2055 SELECT o.key2056 FROM objects AS o, ct2057 WHERE2058 NOT EXISTS (2059 SELECT 12060 FROM reachable_objects ro2061 WHERE ro.key = o.key2062 )2063 AND NOT EXISTS (2064 SELECT 12065 FROM pending_objects AS po2066 WHERE po.key = o.key2067 )2068 AND o.deleted_at IS NULL -- Only mark fresh objects2069 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2070 FOR UPDATE2071 )2072 UPDATE objects2073 SET2074 deleted_at = ct.now,2075 first_deleted_at = COALESCE(first_deleted_at, ct.now)2076 FROM stale_objects, ct2077 WHERE objects.key = stale_objects.key2078 2079--- PASS: TestGCEndsOnShutdown (0.00s)2080 --- PASS: TestGCEndsOnShutdown/before_the_run (5.89s)2081 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (5.99s)2082 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (6.25s)2083--- PASS: TestPendingClosureWriteTimeout (0.01s)2084 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2085 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2086 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2087 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (6.93s)20882026/10/07 06:19:03 INFO Received uploads request method=POST path=/api/pending_closures20892026/10/07 06:19:03 INFO Aborted multipart uploads count=0 kept=020902026/10/07 06:19:03 WARN Force mode enabled - objects will be deleted immediately without grace period20912026/10/07 06:19:03 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=020922026/10/07 06:19:03 INFO Vacuumed table table=pending_closures20932026/10/07 06:19:03 INFO Vacuumed table table=pending_objects20942026/10/07 06:19:03 INFO Vacuumed table table=multipart_uploads20952026/10/07 06:19:03 INFO Vacuumed table table=closures20962026/10/07 06:19:03 INFO Vacuumed table table=objects2097--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2098 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (5.84s)2099 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (5.73s)21002026/10/07 06:19:03 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21012026/10/07 06:19:03 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.754163029s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21022026/10/07 06:19:03 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21032026/10/07 06:19:05 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"21042026/10/07 06:19:05 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21052026/10/07 06:19:05 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=185.273141ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21062026/10/07 06:19:05 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=427.560313ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21072026/10/07 06:19:06 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=756.321035ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21082026/10/07 06:19:06 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.586397592s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21092026/10/07 06:19:08 WARN Request failed, retrying attempt=1 max_attempts=6 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21102026/10/07 06:19:08 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=181.487493ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21112026/10/07 06:19:08 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=420.475446ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21122026/10/07 06:19:09 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=833.217037ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21132026/10/07 06:19:10 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.461612643s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2114--- PASS: TestClientErrorHandling (0.00s)2115 --- PASS: TestClientErrorHandling/InvalidStorePath (5.39s)2116 --- PASS: TestClientErrorHandling/InvalidAuthToken (4.79s)2117 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.07s)2118PASS2119{"timestamp":"2026-10-07T06:19:11.501738Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53295","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}21202026-10-07 06:19:11.659 UTC [8991] LOG: received smart shutdown request21212026-10-07 06:19:11.661 UTC [8991] LOG: background worker "logical replication launcher" (PID 9002) exited with exit code 121222026-10-07 06:19:13.253 UTC [8996] LOG: checkpoint complete: wrote 10101 buffers (61.7%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=11.695 s, sync=1.018 s, total=12.793 s; sync files=34045, longest=0.001 s, average=0.001 s; distance=533074 kB, estimate=533074 kB; lsn=0/228C8FC0, redo lsn=0/22021A8821232026-10-07 06:19:13.253 UTC [8996] LOG: shutting down21242026-10-07 06:19:13.254 UTC [8996] LOG: checkpoint starting: shutdown immediate21252026-10-07 06:19:13.271 UTC [8996] LOG: checkpoint complete: wrote 426 buffers (2.6%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.011 s, sync=0.007 s, total=0.018 s; sync files=210, longest=0.001 s, average=0.001 s; distance=8861 kB, estimate=480653 kB; lsn=0/228C9038, redo lsn=0/228C903821262026-10-07 06:19:13.300 UTC [8991] LOG: database system is shut down2127Running OIDC tests...2128=== RUN TestAudienceForIssuer2129=== PAUSE TestAudienceForIssuer2130=== RUN TestGlobMatch2131=== PAUSE TestGlobMatch2132=== RUN TestValidateToken_ValidToken2133=== PAUSE TestValidateToken_ValidToken2134=== RUN TestValidateToken_WrongAudience2135=== PAUSE TestValidateToken_WrongAudience2136=== RUN TestValidateToken_Expired2137=== PAUSE TestValidateToken_Expired2138=== RUN TestValidateToken_BoundClaimsMismatch2139=== PAUSE TestValidateToken_BoundClaimsMismatch2140=== RUN TestValidateToken_BoundSubjectMismatch2141=== PAUSE TestValidateToken_BoundSubjectMismatch2142=== RUN TestValidateToken_MultipleProviders2143=== PAUSE TestValidateToken_MultipleProviders2144=== RUN TestValidateToken_NoMatchingProvider2145=== PAUSE TestValidateToken_NoMatchingProvider2146=== RUN TestValidateToken_KubernetesServiceAccount2147=== PAUSE TestValidateToken_KubernetesServiceAccount2148=== RUN TestNewValidator_KubernetesRequiresCA2149=== PAUSE TestNewValidator_KubernetesRequiresCA2150=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2151=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2152=== RUN TestPins_ReservedForMatchingRule2153=== PAUSE TestPins_ReservedForMatchingRule2154=== RUN TestPins_TopLevelShorthand2155=== PAUSE TestPins_TopLevelShorthand2156=== RUN TestPins_ConfigValidation2157=== PAUSE TestPins_ConfigValidation2158=== RUN TestScopes_LegacyProviderDefaultsToWrite2159=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2160=== RUN TestScopes_Rules2161=== PAUSE TestScopes_Rules2162=== RUN TestScopes_ConfigValidation2163=== PAUSE TestScopes_ConfigValidation2164=== CONT TestAudienceForIssuer2165=== CONT TestValidateToken_KubernetesServiceAccount2166=== CONT TestPins_ConfigValidation2167--- PASS: TestAudienceForIssuer (0.00s)2168=== CONT TestValidateToken_NoMatchingProvider2169=== CONT TestValidateToken_MultipleProviders2170=== CONT TestValidateToken_BoundSubjectMismatch2171=== CONT TestValidateToken_BoundClaimsMismatch2172--- PASS: TestPins_ConfigValidation (0.00s)2173=== CONT TestValidateToken_Expired2174=== CONT TestValidateToken_WrongAudience2175=== CONT TestValidateToken_ValidToken2176=== CONT TestGlobMatch2177=== RUN TestGlobMatch/foo_foo2178=== PAUSE TestGlobMatch/foo_foo2179=== RUN TestGlobMatch/foo_bar2180=== PAUSE TestGlobMatch/foo_bar2181=== RUN TestGlobMatch/*_2182=== PAUSE TestGlobMatch/*_2183=== RUN TestGlobMatch/*_anything2184=== PAUSE TestGlobMatch/*_anything2185=== RUN TestGlobMatch/foo*_foo2186=== PAUSE TestGlobMatch/foo*_foo2187=== RUN TestGlobMatch/foo*_foobar2188=== PAUSE TestGlobMatch/foo*_foobar2189=== RUN TestGlobMatch/foo*_bar2190=== PAUSE TestGlobMatch/foo*_bar2191=== RUN TestGlobMatch/*bar_bar2192=== PAUSE TestGlobMatch/*bar_bar2193=== RUN TestGlobMatch/*bar_foobar2194=== PAUSE TestGlobMatch/*bar_foobar2195=== RUN TestGlobMatch/*bar_foo2196=== PAUSE TestGlobMatch/*bar_foo2197=== RUN TestGlobMatch/foo*bar_foobar2198=== PAUSE TestGlobMatch/foo*bar_foobar2199=== CONT TestScopes_Rules2200=== CONT TestScopes_ConfigValidation2201=== CONT TestPins_ReservedForMatchingRule2202=== CONT TestPins_TopLevelShorthand2203--- PASS: TestScopes_ConfigValidation (0.00s)2204=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2205=== CONT TestNewValidator_KubernetesRequiresCA2206=== CONT TestScopes_LegacyProviderDefaultsToWrite2207=== RUN TestGlobMatch/foo*bar_foo123bar2208=== PAUSE TestGlobMatch/foo*bar_foo123bar2209=== RUN TestGlobMatch/foo*bar_foobarbaz2210=== PAUSE TestGlobMatch/foo*bar_foobarbaz2211=== RUN TestGlobMatch/*/*_foo/bar2212=== PAUSE TestGlobMatch/*/*_foo/bar2213=== RUN TestGlobMatch/*/*_foo2214=== PAUSE TestGlobMatch/*/*_foo2215=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2216=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2217=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02218=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02219=== RUN TestGlobMatch/refs/*/main_refs/heads/main2220=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2221=== RUN TestGlobMatch/fo?_foo2222=== PAUSE TestGlobMatch/fo?_foo2223=== RUN TestGlobMatch/fo?_fo2224=== PAUSE TestGlobMatch/fo?_fo2225=== RUN TestGlobMatch/fo?_fooo2226=== PAUSE TestGlobMatch/fo?_fooo2227=== RUN TestGlobMatch/?oo_foo2228=== PAUSE TestGlobMatch/?oo_foo2229=== RUN TestGlobMatch/?oo_boo2230=== PAUSE TestGlobMatch/?oo_boo2231=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2232=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2233=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2234=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2235=== CONT TestGlobMatch/foo_foo2236=== CONT TestGlobMatch/*/*_foo/bar2237=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2238=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2239=== CONT TestGlobMatch/?oo_boo2240=== CONT TestGlobMatch/?oo_foo2241=== CONT TestGlobMatch/fo?_fooo2242=== CONT TestGlobMatch/fo?_fo2243=== CONT TestGlobMatch/fo?_foo2244=== CONT TestGlobMatch/refs/*/main_refs/heads/main2245=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02246=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2247=== CONT TestGlobMatch/*/*_foo2248=== CONT TestGlobMatch/*bar_bar2249=== CONT TestGlobMatch/foo*bar_foobarbaz2250=== CONT TestGlobMatch/foo*bar_foo123bar2251=== CONT TestGlobMatch/foo*bar_foobar2252=== CONT TestGlobMatch/*bar_foo2253=== CONT TestGlobMatch/*bar_foobar2254=== CONT TestGlobMatch/foo*_foo2255=== CONT TestGlobMatch/foo*_bar2256=== CONT TestGlobMatch/foo*_foobar2257=== CONT TestGlobMatch/*_2258=== CONT TestGlobMatch/*_anything2259=== CONT TestGlobMatch/foo_bar2260--- PASS: TestGlobMatch (0.05s)2261 --- PASS: TestGlobMatch/foo_foo (0.00s)2262 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2263 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2264 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2265 --- PASS: TestGlobMatch/?oo_boo (0.00s)2266 --- PASS: TestGlobMatch/?oo_foo (0.00s)2267 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2268 --- PASS: TestGlobMatch/fo?_fo (0.00s)2269 --- PASS: TestGlobMatch/fo?_foo (0.00s)2270 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2271 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2272 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2273 --- PASS: TestGlobMatch/*/*_foo (0.00s)2274 --- PASS: TestGlobMatch/*bar_bar (0.00s)2275 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2276 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2277 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2278 --- PASS: TestGlobMatch/*bar_foo (0.00s)2279 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2280 --- PASS: TestGlobMatch/foo*_foo (0.00s)2281 --- PASS: TestGlobMatch/foo*_bar (0.00s)2282 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2283 --- PASS: TestGlobMatch/*_ (0.00s)2284 --- PASS: TestGlobMatch/*_anything (0.00s)2285 --- PASS: TestGlobMatch/foo_bar (0.00s)22862026/10/07 06:19:15 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:536322287--- PASS: TestValidateToken_KubernetesServiceAccount (0.12s)22882026/10/07 06:19:15 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:53631/oidc22892026/10/07 06:19:15 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:53634/oidc22902026/10/07 06:19:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53637/oidc22912026/10/07 06:19:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53639/oidc2292--- PASS: TestValidateToken_Expired (0.15s)2293--- PASS: TestValidateToken_MultipleProviders (0.15s)22942026/10/07 06:19:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53641/oidc2295--- PASS: TestValidateToken_BoundClaimsMismatch (0.16s)2296--- PASS: TestScopes_Rules (0.16s)22972026/10/07 06:19:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53643/oidc2298--- PASS: TestValidateToken_WrongAudience (0.18s)22992026/10/07 06:19:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53645/oidc2300--- PASS: TestPins_ReservedForMatchingRule (0.19s)23012026/10/07 06:19:15 http: TLS handshake error from 127.0.0.1:53648: read tcp 127.0.0.1:53647->127.0.0.1:53648: use of closed network connection2302--- PASS: TestNewValidator_KubernetesRequiresCA (0.22s)23032026/10/07 06:19:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53649/oidc23042026/10/07 06:19:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53651/oidc2305--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.23s)2306--- PASS: TestPins_TopLevelShorthand (0.24s)23072026/10/07 06:19:15 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232308--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.24s)23092026/10/07 06:19:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53656/oidc2310--- PASS: TestValidateToken_BoundSubjectMismatch (0.29s)23112026/10/07 06:19:16 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:53655/oidc2312--- PASS: TestValidateToken_NoMatchingProvider (0.35s)23132026/10/07 06:19:16 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53660/oidc2314--- PASS: TestValidateToken_ValidToken (0.36s)2315PASS2316Running hook tests...2317=== RUN TestSendPathsEmpty2318=== PAUSE TestSendPathsEmpty2319=== RUN TestQueueEnqueueAndFetch2320=== PAUSE TestQueueEnqueueAndFetch2321=== RUN TestQueueDeduplication2322=== PAUSE TestQueueDeduplication2323=== RUN TestQueueRemove2324=== PAUSE TestQueueRemove2325=== RUN TestQueueFetchBatchLimit2326=== PAUSE TestQueueFetchBatchLimit2327=== RUN TestQueueRetryMovesToBack2328=== PAUSE TestQueueRetryMovesToBack2329=== RUN TestQueueFetchRemoveLifecycle2330=== PAUSE TestQueueFetchRemoveLifecycle2331=== RUN TestQueueConcurrentWriters2332=== PAUSE TestQueueConcurrentWriters2333=== RUN TestQueueRemoveLargeClosure2334=== PAUSE TestQueueRemoveLargeClosure2335=== RUN TestServerClientIntegration2336=== PAUSE TestServerClientIntegration2337=== RUN TestServerQueueError2338=== PAUSE TestServerQueueError2339=== RUN TestGetListenerSocketActivation2340 server_test.go:175: listen: listen unix /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestGetListenerSocketActivation4195885064/001/activated.sock: bind: invalid argument2341--- FAIL: TestGetListenerSocketActivation (0.00s)2342=== RUN TestDrainIsolatesPoisonPath2343=== PAUSE TestDrainIsolatesPoisonPath2344=== RUN TestRunNotBlockedByPoisonHead2345=== PAUSE TestRunNotBlockedByPoisonHead2346=== RUN TestDrainGivesUpWhenServerDown2347=== PAUSE TestDrainGivesUpWhenServerDown2348=== RUN TestFailedPathPrunedByLaterClosure2349=== PAUSE TestFailedPathPrunedByLaterClosure2350=== RUN TestWorkerUploadsAndRemoves2351=== PAUSE TestWorkerUploadsAndRemoves2352=== RUN TestWorkerSkipsGCdPaths2353=== PAUSE TestWorkerSkipsGCdPaths2354=== RUN TestWorkerPrunesClosureDeps2355=== PAUSE TestWorkerPrunesClosureDeps2356=== RUN TestDrainTimeout2357=== PAUSE TestDrainTimeout2358=== CONT TestSendPathsEmpty2359=== CONT TestServerQueueError2360=== CONT TestWorkerUploadsAndRemoves2361=== CONT TestDrainTimeout2362=== CONT TestWorkerPrunesClosureDeps2363=== CONT TestWorkerSkipsGCdPaths2364=== CONT TestQueueRetryMovesToBack2365=== NAME TestServerQueueError2366 server_test.go:110: listen: listen unix /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestServerQueueError2154479510/001/test.sock: bind: invalid argument2367=== CONT TestServerClientIntegration2368 server_test.go:29: listen: listen unix /private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestServerClientIntegration2863305320/001/test.sock: bind: invalid argument2369=== CONT TestQueueRemoveLargeClosure2370=== CONT TestQueueConcurrentWriters2371=== CONT TestQueueFetchRemoveLifecycle2372--- PASS: TestSendPathsEmpty (0.00s)2373=== CONT TestFailedPathPrunedByLaterClosure2374=== CONT TestQueueFetchBatchLimit2375=== CONT TestRunNotBlockedByPoisonHead2376=== CONT TestQueueRemove2377--- FAIL: TestServerQueueError (0.00s)2378=== CONT TestDrainGivesUpWhenServerDown2379--- FAIL: TestServerClientIntegration (0.00s)2380=== CONT TestQueueDeduplication2381=== CONT TestQueueEnqueueAndFetch2382=== CONT TestDrainIsolatesPoisonPath23832026/10/07 06:19:16 INFO Uploading batch count=123842026/10/07 06:19:16 ERROR Upload failed error="upload failed" count=123852026/10/07 06:19:16 INFO Upload queue status pending=323862026/10/07 06:19:16 INFO Uploading batch count=123872026/10/07 06:19:16 ERROR Upload failed error="upload failed" count=123882026/10/07 06:19:16 INFO Upload queue status pending=22389--- PASS: TestQueueRemove (0.01s)2390--- PASS: TestQueueFetchBatchLimit (0.01s)23912026/10/07 06:19:16 INFO Uploading batch count=223922026/10/07 06:19:16 INFO Upload queue status pending=223932026/10/07 06:19:16 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestWorkerSkipsGCdPaths2884088222/002/nonexistent23942026/10/07 06:19:16 INFO Uploading batch count=123952026/10/07 06:19:16 INFO Uploading batch count=123962026/10/07 06:19:16 INFO Uploading batch count=123972026/10/07 06:19:16 INFO Upload queue status pending=223982026/10/07 06:19:16 INFO Uploading batch count=12399--- PASS: TestQueueRetryMovesToBack (0.01s)24002026/10/07 06:19:16 INFO Uploading batch count=224012026/10/07 06:19:16 INFO Uploading batch count=224022026/10/07 06:19:16 ERROR Upload failed error="upload failed" count=224032026/10/07 06:19:16 ERROR Upload failed, will retry later error="upload failed" path=/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestDrainGivesUpWhenServerDown760285288/002/a2404--- PASS: TestQueueDeduplication (0.01s)24052026/10/07 06:19:16 ERROR Upload failed, will retry later error="upload failed" path=/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestDrainGivesUpWhenServerDown760285288/002/b24062026/10/07 06:19:16 INFO Uploading batch count=424072026/10/07 06:19:16 ERROR Upload failed error="upload failed" count=42408--- PASS: TestQueueEnqueueAndFetch (0.01s)24092026/10/07 06:19:16 ERROR Upload failed, will retry later error="upload failed" path=/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestDrainIsolatesPoisonPath2314588076/002/bbb24102026/10/07 06:19:16 INFO Uploading batch count=224112026/10/07 06:19:16 ERROR Upload failed error="upload failed" count=224122026/10/07 06:19:16 ERROR Upload failed, will retry later error="upload failed" path=/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestDrainGivesUpWhenServerDown760285288/002/c24132026/10/07 06:19:16 ERROR Upload failed, will retry later error="upload failed" path=/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestDrainGivesUpWhenServerDown760285288/002/d2414--- PASS: TestQueueFetchRemoveLifecycle (0.01s)24152026/10/07 06:19:16 INFO Uploading batch count=224162026/10/07 06:19:16 ERROR Upload failed error="upload failed" count=224172026/10/07 06:19:16 ERROR Upload failed, will retry later error="upload failed" path=/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestDrainGivesUpWhenServerDown760285288/002/e24182026/10/07 06:19:16 INFO Uploading batch count=124192026/10/07 06:19:16 ERROR Upload failed error="upload failed" count=12420--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)24212026/10/07 06:19:16 ERROR Upload failed, will retry later error="upload failed" path=/private/var/lib/tribuchet/a5/scratch/da78deaa492c6417/build/TestDrainGivesUpWhenServerDown760285288/002/f24222026/10/07 06:19:16 INFO Uploading batch count=124232026/10/07 06:19:16 ERROR Upload failed error="upload failed" count=124242026/10/07 06:19:16 ERROR Drain finished with paths left in queue remaining=1024252026/10/07 06:19:16 INFO Uploading batch count=124262026/10/07 06:19:16 ERROR Upload failed error="upload failed" count=124272026/10/07 06:19:16 ERROR Drain finished with paths left in queue remaining=12428--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2429--- PASS: TestDrainIsolatesPoisonPath (0.01s)2430--- PASS: TestWorkerUploadsAndRemoves (0.03s)2431--- PASS: TestWorkerPrunesClosureDeps (0.03s)2432--- PASS: TestWorkerSkipsGCdPaths (0.03s)2433--- PASS: TestQueueRemoveLargeClosure (0.04s)2434--- PASS: TestQueueConcurrentWriters (0.16s)24352026/10/07 06:19:16 ERROR Upload failed error="context deadline exceeded" count=224362026/10/07 06:19:16 ERROR Drain finished with paths left in queue remaining=42437--- PASS: TestDrainTimeout (0.21s)24382026/10/07 06:19:17 INFO Uploading batch count=124392026/10/07 06:19:17 INFO Uploading batch count=124402026/10/07 06:19:17 INFO Uploading batch count=124412026/10/07 06:19:17 ERROR Upload failed error="upload failed" count=124422026/10/07 06:19:17 INFO Uploading batch count=124432026/10/07 06:19:17 ERROR Upload failed error="upload failed" count=124442026/10/07 06:19:17 INFO Uploading batch count=124452026/10/07 06:19:17 ERROR Upload failed error="upload failed" count=124462026/10/07 06:19:17 INFO Uploading batch count=124472026/10/07 06:19:17 ERROR Upload failed error="upload failed" count=124482026/10/07 06:19:17 ERROR Drain finished with paths left in queue remaining=12449--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2450FAIL