niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #396
· 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.19s)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 TestDoWithRetry_BodyReplayedViaGetBody101=== CONT TestSetClientTLSErrors102=== CONT TestScriptTokenEmptyCommand103--- PASS: TestScriptTokenEmptyCommand (0.00s)104=== CONT TestEncodeNixBase32WithRealHash105--- PASS: TestEncodeNixBase32WithRealHash (0.00s)106=== CONT TestUploadMultipart_PartsInParallel107=== CONT TestScriptTokenScriptFails108=== CONT TestScriptTokenBadJSON109=== CONT TestScriptTokenEmptyToken110=== CONT TestScriptTokenCachesUntilRefresh111=== CONT TestScriptTokenNoExpiryRerunsEveryCall112=== CONT TestFileTokenEmpty113=== CONT TestFileTokenMissing114=== CONT TestFileTokenReadsAndCaches115=== CONT TestStaticToken116=== CONT TestDumpPathMatchesNix117=== CONT TestEncodeNixBase32118=== CONT TestResolveStorePath119=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess120=== CONT TestRateLimiterFeedback121=== CONT TestPathInfoCACompatibility122=== CONT TestParsePathInfoJSONMultiplePaths123=== CONT TestParsePathInfoJSON124=== CONT TestPathInfoHashCompatibility125=== CONT TestGetStorePathHash126=== CONT TestConvertHashToNix32127=== CONT TestStreamPushGivesUpOnDeadServer128=== RUN TestSetClientTLSErrors/missing_cert_file129--- PASS: TestFileTokenEmpty (0.00s)130=== CONT TestDumpPathSingleFile131=== RUN TestPathInfoCACompatibility/null_ca_field132=== PAUSE TestPathInfoCACompatibility/null_ca_field133=== RUN TestPathInfoCACompatibility/old_string_format_-_text134=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text135=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive136=== RUN TestRateLimiterFeedback/429_enables_limiter137=== PAUSE TestRateLimiterFeedback/429_enables_limiter138=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive139=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths140=== RUN TestGetStorePathHash/valid_store_path141=== RUN TestParsePathInfoJSON/Nix_format142=== PAUSE TestGetStorePathHash/valid_store_path143=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)144=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)145=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths146=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths147=== RUN TestGetStorePathHash/basename_without_hyphen_should_error148=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error149=== CONT TestDumpPathWriterError150=== RUN TestRateLimiterFeedback/503_enables_limiter151=== PAUSE TestRateLimiterFeedback/503_enables_limiter152=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter153=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter154=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter155=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter156=== PAUSE TestParsePathInfoJSON/Nix_format157=== RUN TestParsePathInfoJSON/Lix_format158=== PAUSE TestParsePathInfoJSON/Lix_format159=== RUN TestParsePathInfoJSON/empty_input160=== PAUSE TestParsePathInfoJSON/empty_input161=== RUN TestParsePathInfoJSON/whitespace_only162=== PAUSE TestParsePathInfoJSON/whitespace_only163=== RUN TestParsePathInfoJSON/invalid_JSON164=== PAUSE TestParsePathInfoJSON/invalid_JSON165=== RUN TestPathInfoCACompatibility/new_structured_format_-_text166=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text167=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method168=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method169=== CONT TestUploadMultipart_SupersededByPeer170=== RUN TestUploadMultipart_SupersededByPeer/exists171=== PAUSE TestUploadMultipart_SupersededByPeer/exists172=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths173=== RUN TestUploadMultipart_SupersededByPeer/missing174=== PAUSE TestUploadMultipart_SupersededByPeer/missing175=== PAUSE TestSetClientTLSErrors/missing_cert_file176=== RUN TestSetClientTLSErrors/missing_key_file177=== PAUSE TestSetClientTLSErrors/missing_key_file178=== RUN TestSetClientTLSErrors/missing_ca_file179=== PAUSE TestSetClientTLSErrors/missing_ca_file180=== CONT TestPartSizeForNAR181=== RUN TestPartSizeForNAR/zero_stays_at_minimum182=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum183--- PASS: TestScriptTokenScriptFails (0.01s)184--- PASS: TestStaticToken (0.00s)185=== RUN TestConvertHashToNix32/SRI_format_to_Nix32186=== RUN TestEncodeNixBase32/test_string_hash187=== PAUSE TestEncodeNixBase32/test_string_hash188=== RUN TestEncodeNixBase32/empty_input189=== PAUSE TestEncodeNixBase32/empty_input190=== RUN TestPartSizeForNAR/small_stays_at_minimum191=== PAUSE TestPartSizeForNAR/small_stays_at_minimum192=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum193--- PASS: TestDoServerRequestAttachesToken (0.01s)194=== CONT TestSetClientTLSDoesNotMutateDefaultTransport1952026/10/07 09:36:03 WARN Rate limiter enabled after throttle name=server-test rate=51962026/10/07 09:36:03 WARN Request returned retryable status, retrying attempt=1 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:58584197=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error198=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error199=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error200=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error201=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon202=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon203=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI2042026/10/07 09:36:03 WARN Rate limiter enabled after throttle name=server-test rate=5205--- PASS: TestFileTokenMissing (0.00s)2062026/10/07 09:36:03 ERROR Upload failed error="connection refused" count=202072026/10/07 09:36:03 ERROR Server seems unavailable, giving up on batch untried=17208=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum209--- PASS: TestFileTokenReadsAndCaches (0.00s)210=== CONT TestStreamPushRequestLine211=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI212=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512213=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512214=== RUN TestSetClientTLSErrors/invalid_ca_file215=== PAUSE TestSetClientTLSErrors/invalid_ca_file216=== CONT TestShellSplitErrors217--- PASS: TestShellSplitErrors (0.00s)218=== CONT TestStreamPushBatchesUnderLoad219=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32220=== CONT TestClientSignaturesByStorePath221=== CONT TestStreamPushReportsEveryPath222=== CONT TestStreamPushReportsSignatures223=== CONT TestShellSplit2242026/10/07 09:36:03 WARN Rate limiter backed off name=server-test rate=5225=== RUN TestConvertHashToNix32/already_Nix32_format2262026/10/07 09:36:03 WARN Request returned retryable status, retrying attempt=2 max_attempts=6 backoff=0s status=503 url=http://127.0.0.1:58584227=== PAUSE TestConvertHashToNix32/already_Nix32_format228=== RUN TestConvertHashToNix32/invalid_format229--- PASS: TestClientSignaturesByStorePath (0.00s)230=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun231=== PAUSE TestConvertHashToNix32/invalid_format232=== CONT TestStreamPushIsolatesFailures233=== CONT TestSetClientTLS234=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica235=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts236--- PASS: TestShellSplit (0.00s)237=== CONT TestRegisterUploadedObjectReusesConnections238=== CONT TestFilterOversizedClosures239--- PASS: TestStreamPushReportsEveryPath (0.00s)240=== RUN TestFilterOversizedClosures/no_limit_keeps_everything241=== CONT TestRateLimiterFeedback/429_enables_limiter242=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts243=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything244--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)245=== RUN TestPartSizeForNAR/1_TiB246=== PAUSE TestPartSizeForNAR/1_TiB2472026/10/07 09:36:03 ERROR Upload failed error="bad path" count=3248=== RUN TestPartSizeForNAR/5_TiB_S3_max_object249=== CONT TestCaseHackSuffix250--- PASS: TestStreamPushIsolatesFailures (0.00s)251=== CONT TestParsePathInfoJSON/Nix_format2522026/10/07 09:36:03 ERROR Upload failed error=boom count=1253--- PASS: TestStreamPushReportsSignatures (0.00s)254=== CONT TestPathInfoCACompatibility/null_ca_field2552026/10/07 09:36:03 ERROR Upload failed error=boom count=1256=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter257=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter258=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped259=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped260=== RUN TestFilterOversizedClosures/all_closures_skipped261=== PAUSE TestFilterOversizedClosures/all_closures_skipped262=== CONT TestParsePathInfoJSON/invalid_JSON263=== CONT TestParsePathInfoJSON/whitespace_only264=== CONT TestParsePathInfoJSON/empty_input265=== CONT TestParsePathInfoJSON/Lix_format266=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths267=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method268=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive269=== CONT TestPathInfoCACompatibility/old_string_format_-_text270=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths271=== CONT TestUploadMultipart_SupersededByPeer/exists272--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)273--- PASS: TestScriptTokenBadJSON (0.02s)274--- PASS: TestParsePathInfoJSON (0.00s)275 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)276 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)277 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)278 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)279 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)280=== CONT TestPathInfoCACompatibility/new_structured_format_-_text281=== CONT TestUploadMultipart_SupersededByPeer/missing282=== CONT TestRateLimiterFeedback/503_enables_limiter283--- PASS: TestPathInfoCACompatibility (0.00s)284 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)285 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)286 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)287 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)288 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)289--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)290 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)291 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)292=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object293=== RUN TestPartSizeForNAR/capped_at_5_GiB294=== PAUSE TestPartSizeForNAR/capped_at_5_GiB295=== CONT TestEncodeNixBase32/test_string_hash296=== CONT TestEncodeNixBase32/empty_input297--- PASS: TestEncodeNixBase32 (0.00s)298 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)299 --- PASS: TestEncodeNixBase32/empty_input (0.00s)300=== CONT TestGetStorePathHash/valid_store_path301=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error302=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error303=== CONT TestGetStorePathHash/basename_without_hyphen_should_error304--- PASS: TestGetStorePathHash (0.00s)305 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)306 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)307 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)308 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)309=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)310=== CONT TestSetClientTLSErrors/missing_cert_file311--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)312=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512313=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI314=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon315=== CONT TestSetClientTLSErrors/invalid_ca_file316--- PASS: TestPathInfoHashCompatibility (0.00s)317 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)318 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)319 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)320 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)321=== CONT TestSetClientTLSErrors/missing_ca_file322=== CONT TestSetClientTLSErrors/missing_key_file323=== CONT TestConvertHashToNix32/invalid_format324=== CONT TestConvertHashToNix32/SRI_format_to_Nix32325=== CONT TestFilterOversizedClosures/no_limit_keeps_everything326=== CONT TestFilterOversizedClosures/all_closures_skipped3272026/10/07 09:36:03 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50328=== CONT TestConvertHashToNix32/already_Nix32_format329--- PASS: TestConvertHashToNix32 (0.00s)330 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)331 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)332 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)333=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped334=== CONT TestPartSizeForNAR/zero_stays_at_minimum335--- PASS: TestResolveStorePath (0.01s)336--- PASS: TestSetClientTLSErrors (0.02s)337 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)338 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)339 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)340 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)341=== CONT TestPartSizeForNAR/capped_at_5_GiB342=== CONT TestPartSizeForNAR/5_TiB_S3_max_object343=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts344=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum345=== CONT TestPartSizeForNAR/small_stays_at_minimum346=== CONT TestPartSizeForNAR/1_TiB3472026/10/07 09:36:04 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=2000348--- PASS: TestFilterOversizedClosures (0.00s)349 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)350 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)351 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)3522026/10/07 09:36:04 INFO Garbage collection started353--- PASS: TestScriptTokenEmptyToken (0.02s)354--- PASS: TestPartSizeForNAR (0.00s)355 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)356 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)357 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)358 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)359 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)360 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)361 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)3622026/10/07 09:36:04 WARN Rate limiter enabled after throttle name=server-test rate=53632026/10/07 09:36:04 INFO Garbage collection started3642026/10/07 09:36:04 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=503 url=http://127.0.0.1:586273652026/10/07 09:36:04 WARN Rate limiter enabled after throttle name=server-test rate=53662026/10/07 09:36:04 WARN Request returned retryable status, retrying attempt=1 max_attempts=2 backoff=0s status=429 url=http://127.0.0.1:586393672026/10/07 09:36:04 WARN Rate limiter backed off name=server-test rate=53682026/10/07 09:36:04 WARN Rate limiter backed off name=server-test rate=5369--- PASS: TestRateLimiterFeedback (0.00s)370 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)371 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)372 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.02s)373 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.02s)374--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)375--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)376 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)377 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.02s)378=== RUN TestSetClientTLS/rejects_connection_without_client_cert379=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert380=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA381=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA382=== RUN TestSetClientTLS/preserves_debug_logging_transport383=== PAUSE TestSetClientTLS/preserves_debug_logging_transport384=== CONT TestSetClientTLS/rejects_connection_without_client_cert385=== CONT TestSetClientTLS/preserves_debug_logging_transport386=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA387--- PASS: TestStreamPushRequestLine (0.02s)3882026/10/07 09:36:04 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=03892026/10/07 09:36:04 WARN Garbage collection finished on another replica. Its statistics are not available here390--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)391--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)392--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)3932026/10/07 09:36:04 http: TLS handshake error from 127.0.0.1:58675: remote error: tls: bad certificate394--- PASS: TestSetClientTLS (0.02s)395 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)396 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)397 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)398--- PASS: TestScriptTokenCachesUntilRefresh (0.06s)399--- PASS: TestDumpPathWriterError (0.06s)400--- PASS: TestDumpPathSingleFile (0.07s)401--- PASS: TestCaseHackSuffix (0.06s)402--- PASS: TestDumpPathMatchesNix (0.09s)403--- PASS: TestStreamPushBatchesUnderLoad (0.11s)404--- PASS: TestUploadMultipart_PartsInParallel (0.64s)405--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)406PASS407Running server tests...408The files belonging to this database system will be owned by user "_tribuchetbld3".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/tb/3/scratch/57f3bbd2d234d1c0/build/postgres1549200074/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/tb/3/scratch/57f3bbd2d234d1c0/build/postgres1549200074/data -l logfile start4344352026-10-07 09:36:05.837 UTC [92162] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4362026-10-07 09:36:05.837 UTC [92162] LOG: listening on Unix socket "/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/postgres1549200074/.s.PGSQL.5432"4372026-10-07 09:36:05.839 UTC [92169] LOG: database system was shut down at 2026-10-07 09:36:05 UTC4382026-10-07 09:36:05.839 UTC [92170] FATAL: the database system is starting up439/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/postgres1549200074:5432 - rejecting connections4402026-10-07 09:36:05.840 UTC [92162] LOG: database system is ready to accept connections441/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/postgres1549200074:5432 - accepting connections442{"timestamp":"2026-10-07T09:36:06.082331Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"0046dd17-6de0-4615-b512-6a88a8f7115a","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":8,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}443{"timestamp":"2026-10-07T09:36:06.193532Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"9198585c-655c-4876-9351-42fbaf882841","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(10)"}444{"timestamp":"2026-10-07T09:36:06.297863Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"ee5ddcbf-5d34-4e81-a517-ac1b1319853a","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}445=== RUN TestService_AuthMiddleware446=== PAUSE TestService_AuthMiddleware447=== RUN TestService_AuthMiddleware_MTLSProxyHeader448=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader449=== RUN TestService_AuthMiddleware_MTLSBoundSubjects450=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects451=== RUN TestService_ReadAuthMiddleware452=== PAUSE TestService_ReadAuthMiddleware453=== RUN TestService_AuthMiddleware_OIDC454=== PAUSE TestService_AuthMiddleware_OIDC455=== RUN TestService_RequireScope_OIDC456=== PAUSE TestService_RequireScope_OIDC457=== RUN TestService_ReadScope_PublicByDefault458=== PAUSE TestService_ReadScope_PublicByDefault459=== RUN TestCacheConfigHandler460=== PAUSE TestCacheConfigHandler461=== RUN TestCacheStatsHandler462=== PAUSE TestCacheStatsHandler463=== RUN TestClientCADerivations464=== PAUSE TestClientCADerivations465=== RUN TestClientErrorHandling466=== PAUSE TestClientErrorHandling467=== RUN TestClientIntegration468=== PAUSE TestClientIntegration469=== RUN TestClientMultipleUploads470=== PAUSE TestClientMultipleUploads471=== RUN TestClientWithDependencies472=== PAUSE TestClientWithDependencies473=== RUN TestClientSharedPathCommittedMidPush474=== PAUSE TestClientSharedPathCommittedMidPush475=== RUN TestPinProtectsFromGC476=== PAUSE TestPinProtectsFromGC477=== RUN TestClientPushesUseOnePush478=== PAUSE TestClientPushesUseOnePush479=== RUN TestClientFallsBackToClosures480=== PAUSE TestClientFallsBackToClosures481=== RUN TestDeleteClosuresRacingPins482=== PAUSE TestDeleteClosuresRacingPins483=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock484=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock485=== RUN TestResolveDBConnectionString486=== PAUSE TestResolveDBConnectionString487=== RUN TestConnectWaitsForAPeerMigration488=== PAUSE TestConnectWaitsForAPeerMigration489=== RUN TestLeadElectsOneAndHandsOver490=== PAUSE TestLeadElectsOneAndHandsOver491=== RUN TestLeadIncumbentWinsAfterRestart4922026/10/07 09:36:06 INFO lead: acquired remote=192.0.2.1:12344932026/10/07 09:36:07 INFO lead: released remote=192.0.2.1:12344942026/10/07 09:36:07 INFO lead: acquired remote=192.0.2.1:12344952026/10/07 09:36:08 INFO lead: released remote=192.0.2.1:1234496--- PASS: TestLeadIncumbentWinsAfterRestart (2.03s)497=== RUN TestLeadIncumbentAnnouncesAtOnce498=== PAUSE TestLeadIncumbentAnnouncesAtOnce499=== RUN TestLeadEndsOnShutdown500=== PAUSE TestLeadEndsOnShutdown501=== RUN TestLeadEndsWhenItsConnectionHangs5022026/10/07 09:36:08 INFO lead: acquired remote=192.0.2.1:12345032026-10-07 09:36:10.012 UTC [92209] FATAL: terminating connection due to administrator command5042026/10/07 09:36:10 INFO lead: acquired remote=192.0.2.1:12345052026/10/07 09:36:11 WARN lead: lock connection lost error="timeout: context deadline exceeded"5062026/10/07 09:36:11 INFO lead: released remote=192.0.2.1:12345072026/10/07 09:36:11 INFO lead: released remote=192.0.2.1:1234508--- PASS: TestLeadEndsWhenItsConnectionHangs (2.97s)509=== RUN TestGCAdvisoryLockBlocksConcurrentRun510=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun511=== RUN TestGCBugBareHashReferences512=== PAUSE TestGCBugBareHashReferences513=== RUN TestGCMetrics514=== PAUSE TestGCMetrics515=== RUN TestPushDedupSurvivesConcurrentGC516=== PAUSE TestPushDedupSurvivesConcurrentGC517=== RUN TestDeduplicatedObjectsRecordedAsPending518=== PAUSE TestDeduplicatedObjectsRecordedAsPending519=== RUN TestGCSweepSkipsPendingObjects520=== PAUSE TestGCSweepSkipsPendingObjects521=== RUN TestTombstonedObjectOfferedWithoutWaiting522=== PAUSE TestTombstonedObjectOfferedWithoutWaiting523=== RUN TestGCSweepDeliversEachKeyOnce524=== PAUSE TestGCSweepDeliversEachKeyOnce525=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection526=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection527=== RUN TestForceGCDuringPushOffersSweptObject528=== PAUSE TestForceGCDuringPushOffersSweptObject529=== RUN TestFailedS3DeleteKeepsTombstone530=== PAUSE TestFailedS3DeleteKeepsTombstone531=== RUN TestSweepSkipsRowsLockedByPush532=== PAUSE TestSweepSkipsRowsLockedByPush533=== RUN TestRegisterCompletedObjectNeedsPendingRow534=== PAUSE TestRegisterCompletedObjectNeedsPendingRow535=== RUN TestGetExistingObjectsLocksRows536=== PAUSE TestGetExistingObjectsLocksRows537=== RUN TestSweepRechecksPendingAfterLocking538=== PAUSE TestSweepRechecksPendingAfterLocking539=== RUN TestPushWaitsForSweepHoldingRow540=== PAUSE TestPushWaitsForSweepHoldingRow541=== RUN TestCommitRacingPendingCleanupKeepsObjects542=== PAUSE TestCommitRacingPendingCleanupKeepsObjects543=== RUN TestGCEndsOnShutdown544=== PAUSE TestGCEndsOnShutdown545=== RUN TestGCTaskStore_StartNew546=== PAUSE TestGCTaskStore_StartNew547=== RUN TestGCTaskStore_DeduplicateSameParams548=== PAUSE TestGCTaskStore_DeduplicateSameParams549=== RUN TestGCTaskStore_ConflictDifferentParams550=== PAUSE TestGCTaskStore_ConflictDifferentParams551=== RUN TestGCTaskStore_GetEmpty552=== PAUSE TestGCTaskStore_GetEmpty553=== RUN TestGCTaskStore_GetReturnsLatest554=== PAUSE TestGCTaskStore_GetReturnsLatest555=== RUN TestGCTaskStore_CompletedAllowsNewTask556=== PAUSE TestGCTaskStore_CompletedAllowsNewTask557=== RUN TestGCTaskStore_PhaseUpdates558=== PAUSE TestGCTaskStore_PhaseUpdates559=== RUN TestGCTaskStore_Fail560=== PAUSE TestGCTaskStore_Fail561=== RUN TestGracefulShutdownDrainsInflight562=== PAUSE TestGracefulShutdownDrainsInflight563=== RUN TestService_healthCheckHandler564=== PAUSE TestService_healthCheckHandler565=== RUN TestService_readinessHandler566=== PAUSE TestService_readinessHandler567=== RUN TestGenerateLandingPage568=== PAUSE TestGenerateLandingPage569=== RUN TestCacheConfigHandlerMaxNarSize570=== PAUSE TestCacheConfigHandlerMaxNarSize571=== RUN TestCreatePendingClosureRejectsOversizedNAR572=== PAUSE TestCreatePendingClosureRejectsOversizedNAR573=== RUN TestNARDeduplicationMetadataUploadBug574=== PAUSE TestNARDeduplicationMetadataUploadBug575=== RUN TestMetricsInventory576=== PAUSE TestMetricsInventory577=== RUN TestMetricsCommit578=== PAUSE TestMetricsCommit579=== RUN TestService_NativeMTLS580=== PAUSE TestService_NativeMTLS581=== RUN TestServerTLSConfig582=== PAUSE TestServerTLSConfig583=== RUN TestMultipartCleanup584=== PAUSE TestMultipartCleanup585=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded586=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded587=== RUN TestPendingCleanupUsesOneCutoff588=== PAUSE TestPendingCleanupUsesOneCutoff589=== RUN TestObjectStatsTrigger590=== PAUSE TestObjectStatsTrigger591=== RUN TestObjectStatsLargeCommit592=== PAUSE TestObjectStatsLargeCommit593=== RUN TestOrphanedObjectsGC594=== PAUSE TestOrphanedObjectsGC595=== RUN TestOrphanedObjectsGCStressTest596=== PAUSE TestOrphanedObjectsGCStressTest597=== RUN TestCreatePin_ReservedPins598=== PAUSE TestCreatePin_ReservedPins599=== RUN TestPresentReportsOnlyClosureRoots600=== PAUSE TestPresentReportsOnlyClosureRoots601=== RUN TestPresentRefreshesOnlyStaleClosures602=== PAUSE TestPresentRefreshesOnlyStaleClosures603=== RUN TestPresentNotReportedWhileGCDeletesClosure604=== PAUSE TestPresentNotReportedWhileGCDeletesClosure605=== RUN TestParseSingleRange606=== PAUSE TestParseSingleRange607=== RUN TestProxyHeadersOnlyTrustedOnSocket6082026/10/07 09:36:11 INFO Starting HTTP server address=proxy.sock6092026/10/07 09:36:11 INFO Starting HTTP server address=127.0.0.1:587046102026/10/07 09:36:11 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6112026/10/07 09:36:11 INFO Shutdown signal received, draining in-flight requests timeout=10s612--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)613=== RUN TestIsValidCachePath614=== PAUSE TestIsValidCachePath615=== RUN TestReadProxyNarinfo616=== PAUSE TestReadProxyNarinfo617=== RUN TestReadProxyNarinfoAlreadyDecompressed618=== PAUSE TestReadProxyNarinfoAlreadyDecompressed619=== RUN TestReadProxyContentNegotiation620=== PAUSE TestReadProxyContentNegotiation621=== RUN TestReadProxyNarStreaming622=== PAUSE TestReadProxyNarStreaming623=== RUN TestReadProxy404624=== PAUSE TestReadProxy404625=== RUN TestReadProxyInvalidPath626=== PAUSE TestReadProxyInvalidPath627=== RUN TestReadProxyHead628=== PAUSE TestReadProxyHead629=== RUN TestReadProxyOutlastsServerWriteTimeout630=== PAUSE TestReadProxyOutlastsServerWriteTimeout631=== RUN TestReadProxyConditionalGet632=== PAUSE TestReadProxyConditionalGet633=== RUN TestReadProxyRootRedirectsToIndexHTML634=== PAUSE TestReadProxyRootRedirectsToIndexHTML635=== RUN TestReadProxyDisabled636=== PAUSE TestReadProxyDisabled637=== RUN TestReadRedirectNar638=== PAUSE TestReadRedirectNar639=== RUN TestReadRedirectKeepsNarinfoProxied640=== PAUSE TestReadRedirectKeepsNarinfoProxied641=== RUN TestReadProxyRangeRequest642=== PAUSE TestReadProxyRangeRequest643=== RUN TestReadRedirectUsesPublicS3URL644=== PAUSE TestReadRedirectUsesPublicS3URL645=== RUN TestPush_OverlappingRootsStoreOneRowPerKey646=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey647=== RUN TestPush_CompleteCommitsEveryRoot648=== PAUSE TestPush_CompleteCommitsEveryRoot649=== RUN TestPush_RepeatedRootCommitsOnce650=== PAUSE TestPush_RepeatedRootCommitsOnce651=== RUN TestPush_CompleteWaitsForCleanupOfThePush652=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush653=== RUN TestPush_RootsAreLockedInByteOrder654=== PAUSE TestPush_RootsAreLockedInByteOrder655=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit656=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit657=== RUN TestPush_RejectsBadRequests658=== PAUSE TestPush_RejectsBadRequests659=== RUN TestPush_SignsNarinfosOfItsPendingObjects660=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects661=== RUN TestRedundantMultipartUpload662=== PAUSE TestRedundantMultipartUpload663=== RUN TestCompleteMultipartUpload_ErrorButObjectExists664=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists665=== RUN TestCompletedNarNotReofferedAcrossClosures666=== PAUSE TestCompletedNarNotReofferedAcrossClosures667=== RUN TestPresignedUploadRegisteredBeforeCommit668=== PAUSE TestPresignedUploadRegisteredBeforeCommit669=== RUN TestService_Rustfstest670=== PAUSE TestService_Rustfstest671=== RUN TestParseSize672=== PAUSE TestParseSize673=== RUN TestSkippedUploadsHandler674=== PAUSE TestSkippedUploadsHandler675=== RUN TestSystemdListenerNotActivated676--- PASS: TestSystemdListenerNotActivated (0.00s)677=== RUN TestWatchdogBeatsWhenHealthy678--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)679=== RUN TestWatchdogSkipsWhenUnhealthy6802026/10/07 09:36:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6812026/10/07 09:36:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6822026/10/07 09:36:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6832026/10/07 09:36:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6842026/10/07 09:36:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6852026/10/07 09:36:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6862026/10/07 09:36:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6872026/10/07 09:36:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6882026/10/07 09:36:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"6892026/10/07 09:36:11 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"690--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)691=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle692=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle693=== RUN TestProxyWriteTimeout694=== PAUSE TestProxyWriteTimeout695=== RUN TestPendingClosureWriteTimeout696=== PAUSE TestPendingClosureWriteTimeout697=== RUN TestIsValidUploadKey698=== PAUSE TestIsValidUploadKey699=== RUN TestUploadHandlersRejectInvalidKeys700=== PAUSE TestUploadHandlersRejectInvalidKeys701=== RUN TestUploadHandlersRejectOversizedBody702=== PAUSE TestUploadHandlersRejectOversizedBody703=== RUN TestService_cleanupPendingClosuresHandler704=== PAUSE TestService_cleanupPendingClosuresHandler705=== RUN TestService_createPendingClosureHandler706=== PAUSE TestService_createPendingClosureHandler707=== RUN TestService_verifyS3Integrity708=== PAUSE TestService_verifyS3Integrity709=== RUN TestCompleteMultipartUnregistered710=== PAUSE TestCompleteMultipartUnregistered711=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT712=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT713=== CONT TestPresignedUploadRegisteredBeforeCommit714=== CONT TestUploadHandlersRejectInvalidKeys715=== CONT TestReadRedirectKeepsNarinfoProxied716=== CONT TestGCTaskStore_DeduplicateSameParams717--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)718=== CONT TestService_verifyS3Integrity719=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info720=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle721=== CONT TestCompletedNarNotReofferedAcrossClosures722=== CONT TestCompleteMultipartUpload_ErrorButObjectExists723=== CONT TestRedundantMultipartUpload724=== CONT TestPush_SignsNarinfosOfItsPendingObjects725=== CONT TestPush_RejectsBadRequests726=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit727=== CONT TestPush_RootsAreLockedInByteOrder728=== CONT TestPush_CompleteWaitsForCleanupOfThePush729=== CONT TestPush_RepeatedRootCommitsOnce730=== CONT TestPush_CompleteCommitsEveryRoot731=== CONT TestPush_OverlappingRootsStoreOneRowPerKey732=== CONT TestReadRedirectUsesPublicS3URL733=== CONT TestReadProxyRangeRequest734=== CONT TestIsValidUploadKey735=== RUN TestIsValidUploadKey/narinfo736=== CONT TestPendingClosureWriteTimeout737=== CONT TestProxyWriteTimeout738=== RUN TestPendingClosureWriteTimeout/empty739=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT740=== CONT TestService_AuthMiddleware741=== CONT TestCompleteMultipartUnregistered742=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info743=== PAUSE TestIsValidUploadKey/narinfo744=== RUN TestProxyWriteTimeout/narinfo745=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal746=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal747=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key748=== PAUSE TestPendingClosureWriteTimeout/empty749=== PAUSE TestProxyWriteTimeout/narinfo750=== RUN TestPendingClosureWriteTimeout/400_objects751=== PAUSE TestPendingClosureWriteTimeout/400_objects752=== RUN TestPendingClosureWriteTimeout/670k_objects753=== RUN TestProxyWriteTimeout/1_GiB_nar754=== PAUSE TestProxyWriteTimeout/1_GiB_nar755=== PAUSE TestPendingClosureWriteTimeout/670k_objects756=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key757=== RUN TestIsValidUploadKey/nar_zst758=== RUN TestProxyWriteTimeout/10_GiB_nar759=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline760=== PAUSE TestProxyWriteTimeout/10_GiB_nar761=== RUN TestProxyWriteTimeout/unknown_size762=== PAUSE TestProxyWriteTimeout/unknown_size763=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline764=== PAUSE TestIsValidUploadKey/nar_zst765=== CONT TestService_createPendingClosureHandler766=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key767=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key768=== RUN TestIsValidUploadKey/nar_xz769=== CONT TestService_cleanupPendingClosuresHandler770=== PAUSE TestIsValidUploadKey/nar_xz771=== CONT TestUploadHandlersRejectOversizedBody772=== RUN TestIsValidUploadKey/nar_plain773=== PAUSE TestIsValidUploadKey/nar_plain774=== RUN TestIsValidUploadKey/listing775=== PAUSE TestIsValidUploadKey/listing776=== RUN TestIsValidUploadKey/build_log777=== PAUSE TestIsValidUploadKey/build_log778=== RUN TestIsValidUploadKey/build_log_home-manager_file779=== PAUSE TestIsValidUploadKey/build_log_home-manager_file780=== RUN TestIsValidUploadKey/build_log_plus_in_name781=== PAUSE TestIsValidUploadKey/build_log_plus_in_name782=== RUN TestIsValidUploadKey/build_log_question_mark783=== PAUSE TestIsValidUploadKey/build_log_question_mark784=== RUN TestIsValidUploadKey/build_log_equals785=== PAUSE TestIsValidUploadKey/build_log_equals786=== RUN TestIsValidUploadKey/realisation787=== PAUSE TestIsValidUploadKey/realisation788=== RUN TestIsValidUploadKey/realisation_plus_in_output789=== PAUSE TestIsValidUploadKey/realisation_plus_in_output790=== RUN TestIsValidUploadKey/nix-cache-info791=== PAUSE TestIsValidUploadKey/nix-cache-info792=== RUN TestIsValidUploadKey/index.html793=== PAUSE TestIsValidUploadKey/index.html794=== RUN TestIsValidUploadKey/narinfo_key,_nar_type795=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type796=== RUN TestIsValidUploadKey/nar_key,_narinfo_type797=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type798=== RUN TestIsValidUploadKey/listing_key,_narinfo_type799=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type800=== RUN TestIsValidUploadKey/traversal801=== PAUSE TestIsValidUploadKey/traversal802=== RUN TestIsValidUploadKey/traversal_nar803=== PAUSE TestIsValidUploadKey/traversal_nar804=== RUN TestIsValidUploadKey/absolute805=== PAUSE TestIsValidUploadKey/absolute806=== RUN TestIsValidUploadKey/empty_key807=== PAUSE TestIsValidUploadKey/empty_key808=== RUN TestIsValidUploadKey/unknown_type809=== PAUSE TestIsValidUploadKey/unknown_type810=== CONT TestObjectStatsLargeCommit811=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart812=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart813=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts814=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts815=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure816=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure817=== CONT TestReadRedirectNar8182026/10/07 09:36:13 INFO Received uploads request method=POST path=/api/pending_closures8192026/10/07 09:36:13 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst8202026/10/07 09:36:13 INFO Received uploads request method=POST path=/api/pending_closures821--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.34s)822=== CONT TestReadProxyDisabled8232026/10/07 09:36:13 INFO Received uploads request method=POST path=/api/pending_closures8242026/10/07 09:36:13 INFO Received uploads request method=POST path=/api/pending_closures825--- PASS: TestReadRedirectKeepsNarinfoProxied (2.06s)826=== CONT TestReadProxyRootRedirectsToIndexHTML8272026/10/07 09:36:14 INFO Received uploads request method=POST path=/api/pending_closures8282026/10/07 09:36:14 INFO Received uploads request method=POST path=/api/pending_closures8292026/10/07 09:36:14 INFO Received uploads request method=POST path=/api/pending_closures8302026/10/07 09:36:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8312026/10/07 09:36:15 INFO Received push request method=POST path=/api/pushes8322026-10-07 09:36:15.387 UTC [92291] ERROR: could not obtain lock on row in relation "closures"8332026-10-07 09:36:15.387 UTC [92291] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT8342026-10-07 09:36:15.390 UTC [92291] ERROR: could not obtain lock on row in relation "closures"8352026-10-07 09:36:15.390 UTC [92291] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT8362026-10-07 09:36:15.396 UTC [92291] ERROR: could not obtain lock on row in relation "closures"8372026-10-07 09:36:15.396 UTC [92291] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT8382026-10-07 09:36:15.396 UTC [92291] ERROR: could not obtain lock on row in relation "closures"8392026-10-07 09:36:15.396 UTC [92291] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT8402026-10-07 09:36:15.402 UTC [92291] ERROR: could not obtain lock on row in relation "closures"8412026-10-07 09:36:15.402 UTC [92291] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT842--- PASS: TestPush_RootsAreLockedInByteOrder (3.61s)843=== CONT TestReadProxyConditionalGet8442026/10/07 09:36:15 INFO Received uploads request method=POST path=/api/pending_closures8452026/10/07 09:36:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8462026/10/07 09:36:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZDJhYmQ2OWQtM2E1Mi00MzZmLWJlZDMtMWUzMGIwNjAyYThhLmU1YjMzZDFlLWY2N2QtNGMzMi1hNzgxLTM0YjhhNmVhODc1NXgxNzkxMzY1NzczNDY5NDcxMDAw parts=128472026/10/07 09:36:15 INFO Received uploads request method=POST path=/api/pending_closures8482026/10/07 09:36:15 INFO Received uploads request method=POST path=/api/pending_closures8492026/10/07 09:36:15 INFO Received push request method=POST path=/api/pushes8502026/10/07 09:36:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8512026/10/07 09:36:16 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDJhYmQ2OWQtM2E1Mi00MzZmLWJlZDMtMWUzMGIwNjAyYThhLmNhMTM3NjIyLTkzMTQtNDkwMC05ODNkLTliYWI0NzZkODJmNHgxNzkxMzY1Nzc1NzUzMTE3MDAw8522026/10/07 09:36:16 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZDJhYmQ2OWQtM2E1Mi00MzZmLWJlZDMtMWUzMGIwNjAyYThhLmNhMTM3NjIyLTkzMTQtNDkwMC05ODNkLTliYWI0NzZkODJmNHgxNzkxMzY1Nzc1NzUzMTE3MDAw parts=1853--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (4.37s)854=== CONT TestReadProxyOutlastsServerWriteTimeout8552026/10/07 09:36:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8562026/10/07 09:36:16 INFO Received push request method=POST path=/api/pushes8572026-10-07 09:36:16.383 UTC [92296] ERROR: Push does not exist: id=18582026-10-07 09:36:16.383 UTC [92296] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE8592026-10-07 09:36:16.383 UTC [92296] STATEMENT: SELECT commit_push($1)860--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (4.57s)861=== CONT TestLeadElectsOneAndHandsOver8622026/10/07 09:36:16 INFO Received complete push request method=POST path=/api/pushes/1/complete8632026/10/07 09:36:16 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZDJhYmQ2OWQtM2E1Mi00MzZmLWJlZDMtMWUzMGIwNjAyYThhLmI1ZmE3MDhmLTlmNTItNGRhNC04Njg1LWNlNzgxNzAwMTUzYngxNzkxMzY1Nzc0MzI1MDM1MDAw parts=128642026/10/07 09:36:16 INFO Received uploads request method=POST path=/api/pending_closures865--- PASS: TestCompletedNarNotReofferedAcrossClosures (4.70s)866=== CONT TestReadProxyHead8672026/10/07 09:36:16 INFO Completed push id=1 objects=4 duration=61.072208ms8682026/10/07 09:36:16 INFO Received push request method=POST path=/api/pushes8692026/10/07 09:36:16 INFO Aborted multipart uploads count=0 kept=08702026/10/07 09:36:16 WARN Force mode enabled - objects will be deleted immediately without grace period8712026/10/07 09:36:16 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=08722026/10/07 09:36:16 INFO Received push request method=POST path=/api/pushes8732026/10/07 09:36:16 INFO Vacuumed table table=pending_closures8742026/10/07 09:36:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8752026/10/07 09:36:16 INFO Vacuumed table table=pending_objects8762026/10/07 09:36:16 INFO Vacuumed table table=multipart_uploads8772026/10/07 09:36:16 INFO Received complete push request method=POST path=/api/pushes/1/complete8782026/10/07 09:36:16 INFO Vacuumed table table=closures8792026/10/07 09:36:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZDJhYmQ2OWQtM2E1Mi00MzZmLWJlZDMtMWUzMGIwNjAyYThhLjNmNmQ2ZjkxLTc3ODEtNDhmMS1hYzVhLWM5YTIxZDMzZjJjYngxNzkxMzY1Nzc0OTU3MTM5MDAw parts=108802026/10/07 09:36:16 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8812026/10/07 09:36:16 INFO Vacuumed table table=objects8822026/10/07 09:36:16 INFO Received complete push request method=POST path=/api/pushes/2/complete8832026/10/07 09:36:16 INFO Completed push id=1 objects=4 duration=49.835792ms8842026/10/07 09:36:16 INFO Completed upload id=1 objects=2 duration=24.348542ms885--- PASS: TestPush_RepeatedRootCommitsOnce (5.14s)8862026/10/07 09:36:16 INFO Completed push id=2 objects=4 duration=4.836375ms887=== CONT TestReadProxyInvalidPath8882026/10/07 09:36:16 INFO Received uploads request method=POST path=/api/pending_closures889--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (5.16s)890=== CONT TestReadProxy4048912026/10/07 09:36:16 INFO Received uploads request method=POST path=/api/pending_closures8922026/10/07 09:36:16 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo8932026/10/07 09:36:16 WARN Found objects in DB but missing from S3, will re-upload count=1894--- PASS: TestService_verifyS3Integrity (5.18s)895=== CONT TestReadProxyNarStreaming8962026/10/07 09:36:17 INFO Received push request method=POST path=/api/pushes8972026/10/07 09:36:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8982026/10/07 09:36:17 INFO Signed narinfos id=1 count=18992026/10/07 09:36:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9002026/10/07 09:36:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9012026/10/07 09:36:17 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9022026/10/07 09:36:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9032026/10/07 09:36:17 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9042026/10/07 09:36:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9052026/10/07 09:36:17 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19062026/10/07 09:36:17 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9072026/10/07 09:36:17 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo908--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (5.47s)909=== CONT TestReadProxyContentNegotiation9102026/10/07 09:36:17 INFO Received uploads request method=POST path=/api/pending_closures911--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (5.77s)912=== CONT TestReadProxyNarinfoAlreadyDecompressed913=== RUN TestPush_RejectsBadRequests/no_objects914=== PAUSE TestPush_RejectsBadRequests/no_objects915=== RUN TestPush_RejectsBadRequests/bad_root916=== PAUSE TestPush_RejectsBadRequests/bad_root917=== RUN TestPush_RejectsBadRequests/root_not_in_objects918=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects919=== RUN TestPush_RejectsBadRequests/no_roots920=== PAUSE TestPush_RejectsBadRequests/no_roots921=== CONT TestGCTaskStore_StartNew922--- PASS: TestGCTaskStore_StartNew (0.00s)923=== CONT TestReadProxyNarinfo9242026/10/07 09:36:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9252026/10/07 09:36:18 INFO Received push request method=POST path=/api/pushes9262026/10/07 09:36:18 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZDJhYmQ2OWQtM2E1Mi00MzZmLWJlZDMtMWUzMGIwNjAyYThhLmRkMThjNTc4LWE0YmQtNDAxOS1hZDJjLTIyYjM2ODYwMGU4MXgxNzkxMzY1Nzc1ODU1MDI0MDAw error="Get \"http://127.0.0.1:1/bucket5/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"9272026/10/07 09:36:18 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZDJhYmQ2OWQtM2E1Mi00MzZmLWJlZDMtMWUzMGIwNjAyYThhLmFmOWJjMTJiLTM2OTctNDE3YS1hOTJiLTQwYTk3Nzc5YmIyZXgxNzkxMzY1Nzc1Nzg2MDg5MDAw parts=129282026/10/07 09:36:18 INFO Received cleanup request method=DELETE path=/api/pending_closures9292026/10/07 09:36:18 INFO Aborted multipart uploads count=1 kept=0930--- PASS: TestRedundantMultipartUpload (6.40s)931=== CONT TestIsValidCachePath932=== RUN TestIsValidCachePath/narinfo933=== PAUSE TestIsValidCachePath/narinfo934=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars935=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars936=== RUN TestIsValidCachePath/nar_zst937=== PAUSE TestIsValidCachePath/nar_zst938=== RUN TestIsValidCachePath/nar_xz939=== PAUSE TestIsValidCachePath/nar_xz940=== RUN TestIsValidCachePath/nar_bz2941=== PAUSE TestIsValidCachePath/nar_bz2942=== RUN TestIsValidCachePath/nar_uncompressed943=== PAUSE TestIsValidCachePath/nar_uncompressed944=== RUN TestIsValidCachePath/ls945=== PAUSE TestIsValidCachePath/ls946=== RUN TestIsValidCachePath/log947=== PAUSE TestIsValidCachePath/log948=== RUN TestIsValidCachePath/realisation949=== PAUSE TestIsValidCachePath/realisation950=== RUN TestIsValidCachePath/nix-cache-info951=== PAUSE TestIsValidCachePath/nix-cache-info952=== RUN TestIsValidCachePath/index.html953=== PAUSE TestIsValidCachePath/index.html954=== RUN TestIsValidCachePath/traversal_parent955=== PAUSE TestIsValidCachePath/traversal_parent956=== RUN TestIsValidCachePath/traversal_in_middle957=== PAUSE TestIsValidCachePath/traversal_in_middle958=== RUN TestIsValidCachePath/invalid_char_e959=== PAUSE TestIsValidCachePath/invalid_char_e960=== RUN TestIsValidCachePath/invalid_char_u961=== PAUSE TestIsValidCachePath/invalid_char_u962=== RUN TestIsValidCachePath/random_path963=== PAUSE TestIsValidCachePath/random_path964=== RUN TestIsValidCachePath/empty965=== PAUSE TestIsValidCachePath/empty966=== RUN TestIsValidCachePath/leading_slash967=== PAUSE TestIsValidCachePath/leading_slash968=== RUN TestIsValidCachePath/wrong_extension969=== PAUSE TestIsValidCachePath/wrong_extension970=== RUN TestIsValidCachePath/short_hash971=== PAUSE TestIsValidCachePath/short_hash972=== CONT TestParseSingleRange973=== RUN TestParseSingleRange/none974=== PAUSE TestParseSingleRange/none975=== RUN TestParseSingleRange/unknown_unit976=== PAUSE TestParseSingleRange/unknown_unit977=== RUN TestParseSingleRange/multi-range_ignored978=== PAUSE TestParseSingleRange/multi-range_ignored979=== RUN TestParseSingleRange/malformed_no_dash980=== PAUSE TestParseSingleRange/malformed_no_dash981=== RUN TestParseSingleRange/malformed_both_empty982=== PAUSE TestParseSingleRange/malformed_both_empty983=== RUN TestParseSingleRange/malformed_end_before_start984=== PAUSE TestParseSingleRange/malformed_end_before_start985=== RUN TestParseSingleRange/closed986=== PAUSE TestParseSingleRange/closed987=== RUN TestParseSingleRange/open-ended988=== PAUSE TestParseSingleRange/open-ended989=== RUN TestParseSingleRange/end_clamped_to_size990=== PAUSE TestParseSingleRange/end_clamped_to_size991=== RUN TestParseSingleRange/suffix992=== PAUSE TestParseSingleRange/suffix993=== RUN TestParseSingleRange/suffix_exceeds_size994=== PAUSE TestParseSingleRange/suffix_exceeds_size995=== RUN TestParseSingleRange/single_byte996=== PAUSE TestParseSingleRange/single_byte997=== RUN TestParseSingleRange/start_past_EOF998=== PAUSE TestParseSingleRange/start_past_EOF999=== RUN TestParseSingleRange/start_far_past_EOF1000=== PAUSE TestParseSingleRange/start_far_past_EOF1001=== CONT TestPresentNotReportedWhileGCDeletesClosure1002=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1003=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1004=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1005=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1006=== CONT TestPresentRefreshesOnlyStaleClosures1007--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.47s)1008=== CONT TestGCEndsOnShutdown1009=== RUN TestGCEndsOnShutdown/before_the_run1010=== PAUSE TestGCEndsOnShutdown/before_the_run1011=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1012=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1013=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1014=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1015=== CONT TestPresentReportsOnlyClosureRoots1016--- PASS: TestReadRedirectUsesPublicS3URL (6.73s)1017=== CONT TestCommitRacingPendingCleanupKeepsObjects1018--- PASS: TestReadProxyRangeRequest (7.14s)1019=== CONT TestCreatePin_ReservedPins10202026/10/07 09:36:19 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58779/oidc10212026/10/07 09:36:19 INFO Received push request method=POST path=/api/pushes10222026/10/07 09:36:19 INFO Received complete push request method=POST path=/api/pushes/1/complete10232026/10/07 09:36:19 INFO Completed push id=1 objects=6 duration=72.187ms1024--- PASS: TestPush_CompleteCommitsEveryRoot (7.67s)1025=== CONT TestPushWaitsForSweepHoldingRow10262026/10/07 09:36:19 WARN Rate limiter enabled after throttle name=s3-test rate=510272026/10/07 09:36:19 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1028=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1029 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101030 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001031--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (7.74s)1032=== CONT TestOrphanedObjectsGCStressTest10332026/10/07 09:36:20 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1034--- PASS: TestService_AuthMiddleware (8.33s)1035=== CONT TestOrphanedObjectsGC10362026/10/07 09:36:20 INFO Received cleanup request method=DELETE path=/api/pending_closures10372026/10/07 09:36:20 INFO Aborted multipart uploads count=0 kept=010382026/10/07 09:36:20 INFO Received uploads request method=POST path=/api/pending_closures10392026/10/07 09:36:20 INFO Received cleanup request method=DELETE path=/api/pending_closures10402026/10/07 09:36:20 INFO Aborted multipart uploads count=1 kept=010412026/10/07 09:36:20 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10422026-10-07 09:36:20.998 UTC [92287] ERROR: Closure does not exist: id=110432026-10-07 09:36:20.998 UTC [92287] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10442026-10-07 09:36:20.998 UTC [92287] STATEMENT: -- name: CommitPendingClosure :one1045 SELECT commit_pending_closure($1::bigint)::bigint1046 1047--- PASS: TestService_cleanupPendingClosuresHandler (9.18s)1048=== CONT TestService_Rustfstest10492026/10/07 09:36:21 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10502026/10/07 09:36:21 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1051--- PASS: TestCompleteMultipartUnregistered (9.45s)1052=== CONT TestSweepRechecksPendingAfterLocking10532026/10/07 09:36:21 INFO Received uploads request method=POST path=/api/pending_closures10542026/10/07 09:36:21 INFO Received uploads request method=POST path=/api/pending_closures10552026/10/07 09:36:21 INFO Received uploads request method=POST path=/api/pending_closures1056--- PASS: TestReadRedirectNar (10.35s)1057=== CONT TestGetExistingObjectsLocksRows1058--- PASS: TestReadProxyDisabled (9.56s)1059=== CONT TestRegisterCompletedObjectNeedsPendingRow1060--- PASS: TestReadProxyRootRedirectsToIndexHTML (9.46s)1061=== CONT TestSweepSkipsRowsLockedByPush1062--- PASS: TestReadProxyConditionalGet (8.44s)1063=== CONT TestFailedS3DeleteKeepsTombstone10642026/10/07 09:36:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10652026/10/07 09:36:24 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZDJhYmQ2OWQtM2E1Mi00MzZmLWJlZDMtMWUzMGIwNjAyYThhLjNmNmRmNmJkLWUyZDYtNGUwZC04NTMzLTg5MTJlMjhmYmNmZngxNzkxMzY1NzgxNzg5ODIxMDAw parts=1010662026/10/07 09:36:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10672026/10/07 09:36:24 INFO Completed upload id=1 objects=2 duration=34.933083ms10682026/10/07 09:36:24 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010692026/10/07 09:36:24 INFO Received uploads request method=POST path=/api/pending_closures10702026/10/07 09:36:24 INFO Starting cleanup of old closures method=DELETE path=/api/closures10712026/10/07 09:36:24 INFO Aborted multipart uploads count=0 kept=010722026/10/07 09:36:24 INFO lead: acquired remote=192.0.2.1:123410732026/10/07 09:36:24 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=010742026/10/07 09:36:24 INFO Vacuumed table table=pending_closures10752026/10/07 09:36:24 INFO Vacuumed table table=pending_objects10762026/10/07 09:36:24 INFO Vacuumed table table=multipart_uploads10772026/10/07 09:36:24 INFO Vacuumed table table=closures10782026/10/07 09:36:24 INFO Vacuumed table table=objects10792026/10/07 09:36:24 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001080--- PASS: TestService_createPendingClosureHandler (12.82s)1081=== CONT TestForceGCDuringPushOffersSweptObject1082=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1083=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1084=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1085=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1086=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1087--- PASS: TestReadProxyHead (8.25s)1088=== CONT TestParseSize1089--- PASS: TestParseSize (0.00s)1090=== CONT TestGCSweepDeliversEachKeyOnce10912026/10/07 09:36:25 INFO lead: released remote=192.0.2.1:12341092--- PASS: TestReadProxy404 (8.69s)1093=== CONT TestTombstonedObjectOfferedWithoutWaiting10942026/10/07 09:36:25 INFO lead: acquired remote=192.0.2.1:12341095--- PASS: TestReadProxyInvalidPath (8.95s)1096=== CONT TestSkippedUploadsHandler10972026/10/07 09:36:25 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001098--- PASS: TestSkippedUploadsHandler (0.00s)1099=== CONT TestGCSweepSkipsPendingObjects1100--- PASS: TestReadProxyNarStreaming (9.18s)1101=== CONT TestClientIntegration1102--- PASS: TestReadProxyContentNegotiation (9.26s)1103=== CONT TestDeduplicatedObjectsRecordedAsPending1104--- PASS: TestReadProxyNarinfoAlreadyDecompressed (9.16s)1105=== CONT TestPushDedupSurvivesConcurrentGC11062026/10/07 09:36:26 INFO lead: released remote=192.0.2.1:12341107--- PASS: TestLeadElectsOneAndHandsOver (10.41s)1108=== CONT TestGCMetrics11092026/10/07 09:36:27 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1110--- PASS: TestReadProxyNarinfo (9.25s)1111=== CONT TestGCBugBareHashReferences1112--- PASS: TestPresentReportsOnlyClosureRoots (9.11s)1113=== CONT TestGCAdvisoryLockBlocksConcurrentRun1114--- PASS: TestPresentRefreshesOnlyStaleClosures (9.46s)1115=== CONT TestLeadEndsOnShutdown11162026/10/07 09:36:28 INFO Aborted multipart uploads count=0 kept=011172026/10/07 09:36:28 WARN Force mode enabled - objects will be deleted immediately without grace period11182026/10/07 09:36:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011192026/10/07 09:36:28 INFO Vacuumed table table=pending_closures11202026/10/07 09:36:28 INFO Vacuumed table table=pending_objects11212026/10/07 09:36:28 INFO Vacuumed table table=multipart_uploads11222026/10/07 09:36:28 INFO Vacuumed table table=closures11232026/10/07 09:36:28 INFO Vacuumed table table=objects1124--- PASS: TestCommitRacingPendingCleanupKeepsObjects (9.77s)1125=== CONT TestClientPushesUseOnePush11262026/10/07 09:36:28 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11272026/10/07 09:36:28 WARN Refused reserved pin name=worker-x86_64-linux11282026/10/07 09:36:28 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11292026/10/07 09:36:28 INFO Received create pin request method=POST path=/api/pins/my-app11302026/10/07 09:36:28 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1131--- PASS: TestCreatePin_ReservedPins (9.42s)1132=== CONT TestLeadIncumbentAnnouncesAtOnce11332026/10/07 09:36:28 INFO Received uploads request method=POST path=/api/pending_closures1134--- PASS: TestPushWaitsForSweepHoldingRow (9.69s)1135=== CONT TestClientFallsBackToClosures1136--- PASS: TestReadProxyOutlastsServerWriteTimeout (13.21s)1137=== CONT TestConnectWaitsForAPeerMigration1138--- PASS: TestService_Rustfstest (8.67s)1139=== CONT TestResolveDBConnectionString1140=== RUN TestResolveDBConnectionString/flag_wins1141=== PAUSE TestResolveDBConnectionString/flag_wins1142=== RUN TestResolveDBConnectionString/file_when_flag_empty1143=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1144=== RUN TestResolveDBConnectionString/missing_file_is_an_error1145=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1146=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1147=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1148=== RUN TestResolveDBConnectionString/nothing_configured1149=== PAUSE TestResolveDBConnectionString/nothing_configured1150=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock11512026/10/07 09:36:30 INFO Aborted multipart uploads count=0 kept=011522026/10/07 09:36:30 WARN Force mode enabled - objects will be deleted immediately without grace period11532026/10/07 09:36:30 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=01154=== NAME TestOrphanedObjectsGC1155 orphaned_objects_gc_test.go:287: GC Test Summary:1156 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1157 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1158 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1159 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1160 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1161--- PASS: TestOrphanedObjectsGC (10.24s)1162=== CONT TestDeleteClosuresRacingPins11632026/10/07 09:36:30 INFO Vacuumed table table=pending_closures11642026/10/07 09:36:30 INFO Vacuumed table table=pending_objects1165--- PASS: TestObjectStatsLargeCommit (18.62s)1166=== CONT TestCacheConfigHandlerMaxNarSize1167--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1168=== CONT TestObjectStatsTrigger11692026/10/07 09:36:30 INFO Vacuumed table table=multipart_uploads11702026/10/07 09:36:30 INFO Vacuumed table table=closures11712026/10/07 09:36:30 INFO Vacuumed table table=objects1172--- PASS: TestSweepRechecksPendingAfterLocking (9.22s)1173=== CONT TestPendingCleanupUsesOneCutoff1174--- PASS: TestGetExistingObjectsLocksRows (8.29s)1175=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1176--- PASS: TestRegisterCompletedObjectNeedsPendingRow (8.20s)1177=== CONT TestPinProtectsFromGC11782026/10/07 09:36:31 INFO Aborted multipart uploads count=0 kept=011792026/10/07 09:36:31 WARN Force mode enabled - objects will be deleted immediately without grace period11802026/10/07 09:36:31 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011812026/10/07 09:36:31 INFO Vacuumed table table=pending_closures11822026/10/07 09:36:31 INFO Vacuumed table table=pending_objects11832026/10/07 09:36:31 INFO Vacuumed table table=multipart_uploads11842026/10/07 09:36:31 INFO Vacuumed table table=closures11852026/10/07 09:36:31 INFO Vacuumed table table=objects11862026/10/07 09:36:31 INFO Aborted multipart uploads count=0 kept=011872026/10/07 09:36:31 WARN Force mode enabled - objects will be deleted immediately without grace period11882026/10/07 09:36:31 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=011892026/10/07 09:36:31 INFO Vacuumed table table=pending_closures11902026/10/07 09:36:31 INFO Vacuumed table table=pending_objects11912026/10/07 09:36:31 INFO Vacuumed table table=multipart_uploads11922026/10/07 09:36:31 INFO Vacuumed table table=closures11932026/10/07 09:36:31 INFO Vacuumed table table=objects1194--- PASS: TestSweepSkipsRowsLockedByPush (8.31s)1195=== CONT TestMultipartCleanup11962026/10/07 09:36:31 INFO Received uploads request method=POST path=/api/pending_closures11972026/10/07 09:36:31 INFO Aborted multipart uploads count=0 kept=011982026/10/07 09:36:31 WARN Force mode enabled - objects will be deleted immediately without grace period11992026/10/07 09:36:32 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12002026/10/07 09:36:32 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1201--- PASS: TestFailedS3DeleteKeepsTombstone (8.14s)1202=== CONT TestServerTLSConfig1203=== RUN TestServerTLSConfig/no_client_CA1204=== PAUSE TestServerTLSConfig/no_client_CA1205=== RUN TestServerTLSConfig/missing_CA_file1206=== PAUSE TestServerTLSConfig/missing_CA_file1207=== RUN TestServerTLSConfig/not_a_PEM_file1208=== PAUSE TestServerTLSConfig/not_a_PEM_file1209=== CONT TestService_NativeMTLS12102026/10/07 09:36:32 INFO Received uploads request method=POST path=/api/pending_closures1211--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.82s)1212=== CONT TestMetricsCommit12132026/10/07 09:36:32 INFO Aborted multipart uploads count=0 kept=012142026/10/07 09:36:32 WARN Force mode enabled - objects will be deleted immediately without grace period12152026/10/07 09:36:32 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=012162026/10/07 09:36:32 INFO Vacuumed table table=pending_closures12172026/10/07 09:36:32 INFO Vacuumed table table=pending_objects12182026/10/07 09:36:32 INFO Vacuumed table table=multipart_uploads12192026/10/07 09:36:32 INFO Vacuumed table table=closures12202026/10/07 09:36:32 INFO Vacuumed table table=objects1221--- PASS: TestGCSweepDeliversEachKeyOnce (8.18s)1222=== CONT TestMetricsInventory12232026/10/07 09:36:32 INFO Received uploads request method=POST path=/api/pending_closures1224--- PASS: TestTombstonedObjectOfferedWithoutWaiting (7.37s)1225=== CONT TestNARDeduplicationMetadataUploadBug12262026/10/07 09:36:33 INFO Received uploads request method=POST path=/api/pending_closures12272026/10/07 09:36:33 INFO Aborted multipart uploads count=0 kept=012282026/10/07 09:36:33 WARN Force mode enabled - objects will be deleted immediately without grace period12292026/10/07 09:36:33 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=012302026/10/07 09:36:33 INFO Vacuumed table table=pending_closures12312026/10/07 09:36:33 INFO Vacuumed table table=pending_objects12322026/10/07 09:36:33 INFO Vacuumed table table=multipart_uploads12332026/10/07 09:36:33 INFO Vacuumed table table=closures12342026/10/07 09:36:33 INFO Vacuumed table table=objects1235--- PASS: TestGCSweepSkipsPendingObjects (7.76s)1236=== CONT TestCreatePendingClosureRejectsOversizedNAR12372026/10/07 09:36:33 INFO Received uploads request method=POST path=/api/pending_closures1238--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1239=== CONT TestService_ReadScope_PublicByDefault1240=== NAME TestClientIntegration1241 client_integration_test.go:286: Created store path: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientIntegration3824302340/002/store/73rgrr87f01afzfi6ykypj58n3w275wn-test-file.txt12422026/10/07 09:36:34 INFO Received uploads request method=POST path=/api/pending_closures1243--- PASS: TestDeduplicatedObjectsRecordedAsPending (7.66s)1244=== CONT TestClientErrorHandling1245=== RUN TestClientErrorHandling/InvalidStorePath1246=== PAUSE TestClientErrorHandling/InvalidStorePath1247=== RUN TestClientErrorHandling/InvalidAuthToken1248=== PAUSE TestClientErrorHandling/InvalidAuthToken1249=== RUN TestClientErrorHandling/ServerNotAvailable1250=== PAUSE TestClientErrorHandling/ServerNotAvailable1251=== CONT TestClientCADerivations12522026/10/07 09:36:34 INFO Received push request method=POST path=/api/pushes12532026/10/07 09:36:34 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12542026/10/07 09:36:34 INFO Uploading 73rgrr87f01afzfi6ykypj58n3w275wn-test-file.txt (152B)12552026/10/07 09:36:34 WARN Failed to register uploaded object key=73rgrr87f01afzfi6ykypj58n3w275wn.ls error="server returned 404: 404 page not found\n"12562026/10/07 09:36:34 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"12572026/10/07 09:36:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12582026/10/07 09:36:34 INFO Signed narinfos id=1 count=112592026/10/07 09:36:34 INFO Uploading 1 narinfos12602026/10/07 09:36:34 INFO Received complete push request method=POST path=/api/pushes/1/complete12612026/10/07 09:36:34 WARN Failed to register uploaded object key=73rgrr87f01afzfi6ykypj58n3w275wn.narinfo error="server returned 404: 404 page not found\n"12622026/10/07 09:36:34 INFO Completed push id=1 objects=3 duration=46.898375ms12632026/10/07 09:36:34 INFO Upload complete. (283ms)12642026/10/07 09:36:34 INFO All 1 paths already cached1265=== NAME TestClientIntegration1266 client_integration_test.go:312: Retrieved narinfo from S3:1267 StorePath: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientIntegration3824302340/002/store/73rgrr87f01afzfi6ykypj58n3w275wn-test-file.txt1268 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1269 Compression: zstd1270 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11271 NarSize: 1521272 References: 1273 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11274 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1275 client_integration_test.go:313: Decompressed .ls content (64 bytes):1276 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1277 client_integration_test.go:316: Testing garbage collection...12782026/10/07 09:36:34 INFO Starting cleanup of old closures method=DELETE path=/api/closures12792026/10/07 09:36:34 INFO Garbage collection started12802026/10/07 09:36:34 INFO Aborted multipart uploads count=0 kept=012812026/10/07 09:36:34 WARN Force mode enabled - objects will be deleted immediately without grace period12822026/10/07 09:36:34 INFO Received uploads request method=POST path=/api/pending_closures12832026/10/07 09:36:34 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=012842026/10/07 09:36:34 INFO Aborted multipart uploads count=0 kept=012852026/10/07 09:36:34 INFO Vacuumed table table=pending_closures12862026/10/07 09:36: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=012872026/10/07 09:36:34 INFO Vacuumed table table=pending_objects12882026/10/07 09:36:34 INFO Vacuumed table table=multipart_uploads12892026/10/07 09:36:34 INFO Vacuumed table table=pending_closures12902026/10/07 09:36:34 INFO Vacuumed table table=closures12912026/10/07 09:36:34 INFO Aborted multipart uploads count=0 kept=012922026/10/07 09:36:34 INFO Vacuumed table table=pending_objects12932026/10/07 09:36:34 INFO Vacuumed table table=multipart_uploads12942026/10/07 09:36:34 INFO Vacuumed table table=objects12952026/10/07 09:36:34 INFO Vacuumed table table=closures12962026/10/07 09:36:34 WARN Force mode enabled - objects will be deleted immediately without grace period12972026/10/07 09:36:35 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012982026/10/07 09:36:35 INFO Vacuumed table table=pending_closures12992026/10/07 09:36:35 INFO Vacuumed table table=pending_objects13002026/10/07 09:36:35 INFO Vacuumed table table=objects13012026/10/07 09:36:35 INFO Vacuumed table table=multipart_uploads13022026/10/07 09:36:35 INFO Vacuumed table table=closures13032026/10/07 09:36:35 INFO Vacuumed table table=objects1304--- PASS: TestGCMetrics (8.27s)1305=== CONT TestCacheStatsHandler13062026/10/07 09:36:35 INFO Aborted multipart uploads count=0 kept=013072026/10/07 09:36:35 WARN Force mode enabled - objects will be deleted immediately without grace period13082026/10/07 09:36:35 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013092026/10/07 09:36:35 INFO Vacuumed table table=pending_closures13102026/10/07 09:36:35 INFO Vacuumed table table=pending_objects13112026/10/07 09:36:35 INFO Vacuumed table table=multipart_uploads13122026/10/07 09:36:35 INFO Vacuumed table table=closures13132026/10/07 09:36:35 INFO Vacuumed table table=objects1314--- PASS: TestPushDedupSurvivesConcurrentGC (8.45s)1315=== CONT TestCacheConfigHandler1316=== RUN TestCacheConfigHandler/full_config,_no_issuer1317=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1318=== RUN TestCacheConfigHandler/no_cache_url_configured1319=== PAUSE TestCacheConfigHandler/no_cache_url_configured1320=== RUN TestCacheConfigHandler/no_signing_keys1321=== PAUSE TestCacheConfigHandler/no_signing_keys1322=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1323=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1324=== CONT TestClientWithDependencies1325--- PASS: TestGCBugBareHashReferences (8.66s)1326=== CONT TestService_ReadAuthMiddleware13272026/10/07 09:36:35 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld3 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1328--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (8.47s)1329=== CONT TestClientSharedPathCommittedMidPush13302026/10/07 09:36:36 INFO lead: acquired remote=192.0.2.1:123413312026/10/07 09:36:36 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01332=== NAME TestClientIntegration1333 client_integration_test.go:323: Objects in database after GC:1334 client_integration_test.go:323: Successfully deleted all objects with GC --force1335--- PASS: TestClientIntegration (10.54s)1336=== CONT TestService_RequireScope_OIDC13372026/10/07 09:36:36 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58931/oidc13382026/10/07 09:36:37 INFO lead: acquired remote=192.0.2.1:123413392026/10/07 09:36:37 INFO lead: released remote=192.0.2.1:12341340--- PASS: TestLeadIncumbentAnnouncesAtOnce (8.76s)1341=== CONT TestService_AuthMiddleware_OIDC13422026/10/07 09:36:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:58935/oidc13432026/10/07 09:36:37 INFO lead: released remote=192.0.2.1:12341344--- PASS: TestLeadEndsOnShutdown (9.57s)1345=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13462026/10/07 09:36:37 INFO Received push request method=POST path=/api/pushes13472026/10/07 09:36:37 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13482026/10/07 09:36:37 INFO Uploading 54ihpkbbm4478wjv59iljakqlkiyhw23-a (256B)13492026/10/07 09:36:37 INFO Uploading b8i6jj1bjsz0zjhjg6sd4bcprwcl95ma-shared-dep (136B)13502026/10/07 09:36:37 WARN Failed to register uploaded object key=b8i6jj1bjsz0zjhjg6sd4bcprwcl95ma.ls error="server returned 404: 404 page not found\n"13512026/10/07 09:36:37 WARN Failed to register uploaded object key=nar/1d77r26hhryldszarc24ng5xqilhy31az2hs59fbq28532vzv9fx.nar.zst error="server returned 404: 404 page not found\n"13522026/10/07 09:36:37 WARN Failed to register uploaded object key=54ihpkbbm4478wjv59iljakqlkiyhw23.ls error="server returned 404: 404 page not found\n"13532026/10/07 09:36:37 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13542026/10/07 09:36:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13552026/10/07 09:36:37 WARN Failed to register uploaded object key=33pd29w98jk16ajsgvj1awcpylf151kp.ls error="server returned 404: 404 page not found\n"13562026/10/07 09:36:37 INFO Signed narinfos id=1 count=313572026/10/07 09:36:37 INFO Uploading 3 narinfos13582026/10/07 09:36:37 WARN Failed to register uploaded object key=b8i6jj1bjsz0zjhjg6sd4bcprwcl95ma.narinfo error="server returned 404: 404 page not found\n"13592026/10/07 09:36:37 WARN Failed to register uploaded object key=54ihpkbbm4478wjv59iljakqlkiyhw23.narinfo error="server returned 404: 404 page not found\n"13602026/10/07 09:36:37 INFO Received complete push request method=POST path=/api/pushes/1/complete13612026/10/07 09:36:37 WARN Failed to register uploaded object key=33pd29w98jk16ajsgvj1awcpylf151kp.narinfo error="server returned 404: 404 page not found\n"13622026/10/07 09:36:37 INFO Completed push id=1 objects=8 duration=38.842375ms13632026/10/07 09:36:37 INFO Upload complete. (294ms)1364=== NAME TestClientPushesUseOnePush1365 client_pushes_test.go:97: Retrieved narinfo from S3:1366 StorePath: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientPushesUseOnePush3708661116/001/store/b8i6jj1bjsz0zjhjg6sd4bcprwcl95ma-shared-dep1367 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1368 Compression: zstd1369 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821370 NarSize: 1361371 References: 1372 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1373 client_pushes_test.go:97: Retrieved narinfo from S3:1374 StorePath: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientPushesUseOnePush3708661116/001/store/54ihpkbbm4478wjv59iljakqlkiyhw23-a1375 URL: nar/1d77r26hhryldszarc24ng5xqilhy31az2hs59fbq28532vzv9fx.nar.zst1376 Compression: zstd1377 NarHash: sha256:1d77r26hhryldszarc24ng5xqilhy31az2hs59fbq28532vzv9fx1378 NarSize: 2561379 References: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientPushesUseOnePush3708661116/001/store/b8i6jj1bjsz0zjhjg6sd4bcprwcl95ma-shared-dep1380 CA: text:sha256:0a5f2ija2lgmjzs524b82yl7bmmnrgh62kwv3bkpqjpsis5lbwni1381 client_pushes_test.go:97: Retrieved narinfo from S3:1382 StorePath: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientPushesUseOnePush3708661116/001/store/33pd29w98jk16ajsgvj1awcpylf151kp-b1383 URL: nar/1d77r26hhryldszarc24ng5xqilhy31az2hs59fbq28532vzv9fx.nar.zst1384 Compression: zstd1385 NarHash: sha256:1d77r26hhryldszarc24ng5xqilhy31az2hs59fbq28532vzv9fx1386 NarSize: 2561387 References: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientPushesUseOnePush3708661116/001/store/b8i6jj1bjsz0zjhjg6sd4bcprwcl95ma-shared-dep1388 CA: text:sha256:0a5f2ija2lgmjzs524b82yl7bmmnrgh62kwv3bkpqjpsis5lbwni1389=== NAME TestOrphanedObjectsGCStressTest1390 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1391--- PASS: TestClientPushesUseOnePush (9.64s)1392=== CONT TestService_AuthMiddleware_MTLSProxyHeader1393=== NAME TestOrphanedObjectsGCStressTest1394 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1395--- PASS: TestConnectWaitsForAPeerMigration (8.80s)1396=== CONT TestGCTaskStore_PhaseUpdates1397--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1398=== CONT TestGCTaskStore_GetEmpty1399--- PASS: TestGCTaskStore_GetEmpty (0.00s)1400=== CONT TestGCTaskStore_CompletedAllowsNewTask1401--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1402=== CONT TestGenerateLandingPage1403--- PASS: TestGenerateLandingPage (0.00s)1404=== CONT TestGCTaskStore_GetReturnsLatest1405--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1406=== CONT TestService_readinessHandler14072026/10/07 09:36:38 INFO Received uploads request method=POST path=/api/pending_closures14082026/10/07 09:36:38 INFO Received uploads request method=POST path=/api/pending_closures14092026/10/07 09:36:38 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14102026/10/07 09:36:38 INFO Uploading i59nn7ym20lvp2jbfjsr959fs1qzz3s9-b (256B)14112026/10/07 09:36:38 INFO Uploading 6i4kzr16kasisvs3xyjchx1vc66rxrzf-shared-dep (136B)14122026/10/07 09:36:38 WARN Failed to register uploaded object key=6i4kzr16kasisvs3xyjchx1vc66rxrzf.ls error="server returned 404: 404 page not found\n"14132026/10/07 09:36:38 WARN Failed to register uploaded object key=nar/1l8d95mk7s13m2xk6241igigsniz0r14fq6bbksx1x3zf1ygw994.nar.zst error="server returned 404: 404 page not found\n"14142026/10/07 09:36:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign14152026/10/07 09:36:38 WARN Failed to register uploaded object key=hnj0ms8anh0w0x387yz9qwd3whmj7q4d.ls error="server returned 404: 404 page not found\n"14162026/10/07 09:36:38 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14172026/10/07 09:36:38 WARN Failed to register uploaded object key=i59nn7ym20lvp2jbfjsr959fs1qzz3s9.ls error="server returned 404: 404 page not found\n"14182026/10/07 09:36:38 INFO Signed narinfos id=2 count=214192026/10/07 09:36:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign14202026/10/07 09:36:38 INFO Signed narinfos id=1 count=214212026/10/07 09:36:38 INFO Uploading 4 narinfos14222026/10/07 09:36:38 WARN Failed to register uploaded object key=i59nn7ym20lvp2jbfjsr959fs1qzz3s9.narinfo error="server returned 404: 404 page not found\n"14232026/10/07 09:36:38 WARN Failed to register uploaded object key=6i4kzr16kasisvs3xyjchx1vc66rxrzf.narinfo error="server returned 404: 404 page not found\n"14242026/10/07 09:36:38 WARN Failed to register uploaded object key=hnj0ms8anh0w0x387yz9qwd3whmj7q4d.narinfo error="server returned 404: 404 page not found\n"1425--- PASS: TestObjectStatsTrigger (8.07s)1426=== CONT TestService_healthCheckHandler14272026/10/07 09:36:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14282026/10/07 09:36:38 WARN Failed to register uploaded object key=6i4kzr16kasisvs3xyjchx1vc66rxrzf.narinfo error="server returned 404: 404 page not found\n"14292026/10/07 09:36:38 INFO Completed upload id=1 objects=6 duration=39.002375ms14302026/10/07 09:36:38 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14312026/10/07 09:36:38 INFO Completed upload id=2 objects=6 duration=702.417µs14322026/10/07 09:36:38 INFO Upload complete. (382ms)1433=== NAME TestClientFallsBackToClosures1434 client_pushes_test.go:112: Retrieved narinfo from S3:1435 StorePath: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientFallsBackToClosures815471893/001/store/6i4kzr16kasisvs3xyjchx1vc66rxrzf-shared-dep1436 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1437 Compression: zstd1438 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821439 NarSize: 1361440 References: 1441 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1442 client_pushes_test.go:112: Retrieved narinfo from S3:1443 StorePath: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientFallsBackToClosures815471893/001/store/hnj0ms8anh0w0x387yz9qwd3whmj7q4d-a1444 URL: nar/1l8d95mk7s13m2xk6241igigsniz0r14fq6bbksx1x3zf1ygw994.nar.zst1445 Compression: zstd1446 NarHash: sha256:1l8d95mk7s13m2xk6241igigsniz0r14fq6bbksx1x3zf1ygw9941447 NarSize: 2561448 References: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientFallsBackToClosures815471893/001/store/6i4kzr16kasisvs3xyjchx1vc66rxrzf-shared-dep1449 CA: text:sha256:0imzivcy8yj5jh3lpjyzslzc0sd0grp8qhxcb5bh4bddqnnaqz1k1450 client_pushes_test.go:112: Retrieved narinfo from S3:1451 StorePath: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientFallsBackToClosures815471893/001/store/i59nn7ym20lvp2jbfjsr959fs1qzz3s9-b1452 URL: nar/1l8d95mk7s13m2xk6241igigsniz0r14fq6bbksx1x3zf1ygw994.nar.zst1453 Compression: zstd1454 NarHash: sha256:1l8d95mk7s13m2xk6241igigsniz0r14fq6bbksx1x3zf1ygw9941455 NarSize: 2561456 References: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientFallsBackToClosures815471893/001/store/6i4kzr16kasisvs3xyjchx1vc66rxrzf-shared-dep1457 CA: text:sha256:0imzivcy8yj5jh3lpjyzslzc0sd0grp8qhxcb5bh4bddqnnaqz1k1458--- PASS: TestClientFallsBackToClosures (9.54s)1459=== CONT TestGCTaskStore_ConflictDifferentParams1460--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1461=== CONT TestGracefulShutdownDrainsInflight14622026/10/07 09:36:38 INFO Starting HTTP server address=127.0.0.1:5897114632026/10/07 09:36:38 INFO Shutdown signal received, draining in-flight requests timeout=10s1464--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1465=== CONT TestGCTaskStore_Fail1466--- PASS: TestGCTaskStore_Fail (0.00s)1467=== CONT TestClientMultipleUploads14682026/10/07 09:36:39 INFO Received uploads request method=POST path=/api/pending_closures1469--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (8.80s)1470=== CONT TestPendingClosureWriteTimeout/empty1471=== CONT TestProxyWriteTimeout/narinfo1472=== CONT TestProxyWriteTimeout/10_GiB_nar1473=== CONT TestProxyWriteTimeout/unknown_size1474=== CONT TestProxyWriteTimeout/1_GiB_nar1475--- PASS: TestProxyWriteTimeout (0.00s)1476 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1477 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1478 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1479 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1480=== CONT TestPendingClosureWriteTimeout/670k_objects1481=== CONT TestPendingClosureWriteTimeout/400_objects1482=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1483--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (9.86s)1484=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info14852026/10/07 09:36:39 INFO Received uploads request method=POST path=/1486=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key14872026/10/07 09:36:39 INFO Received request for more parts method=POST path=/1488=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key14892026/10/07 09:36:39 INFO Received complete multipart upload request method=POST path=/1490=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal14912026/10/07 09:36:39 INFO Received uploads request method=POST path=/1492--- PASS: TestUploadHandlersRejectInvalidKeys (0.01s)1493 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1494 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1495 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1496 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1497=== CONT TestIsValidUploadKey/narinfo1498=== CONT TestIsValidUploadKey/realisation_plus_in_output1499=== CONT TestIsValidUploadKey/unknown_type1500=== CONT TestIsValidUploadKey/empty_key1501=== CONT TestIsValidUploadKey/absolute1502=== CONT TestIsValidUploadKey/traversal_nar1503=== CONT TestIsValidUploadKey/traversal1504=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1505=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1506=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1507=== CONT TestIsValidUploadKey/index.html1508=== CONT TestIsValidUploadKey/nix-cache-info1509=== CONT TestIsValidUploadKey/build_log_home-manager_file1510=== CONT TestIsValidUploadKey/realisation1511=== CONT TestIsValidUploadKey/build_log_equals1512=== CONT TestIsValidUploadKey/build_log_question_mark1513=== CONT TestIsValidUploadKey/build_log_plus_in_name1514=== CONT TestIsValidUploadKey/nar_plain1515=== CONT TestIsValidUploadKey/build_log1516=== CONT TestIsValidUploadKey/listing1517=== CONT TestIsValidUploadKey/nar_xz1518=== CONT TestIsValidUploadKey/nar_zst1519--- PASS: TestIsValidUploadKey (0.01s)1520 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1521 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1522 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1523 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1524 --- PASS: TestIsValidUploadKey/absolute (0.00s)1525 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1526 --- PASS: TestIsValidUploadKey/traversal (0.00s)1527 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1528 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1529 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1530 --- PASS: TestIsValidUploadKey/index.html (0.00s)1531 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1532 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1533 --- PASS: TestIsValidUploadKey/realisation (0.00s)1534 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1535 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1536 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1537 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1538 --- PASS: TestIsValidUploadKey/build_log (0.00s)1539 --- PASS: TestIsValidUploadKey/listing (0.00s)1540 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1541 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1542=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15432026/10/07 09:36:39 INFO Received complete multipart upload request method=POST path=/1544=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure15452026/10/07 09:36:39 INFO Received uploads request method=POST path=/15462026/10/07 09:36:39 INFO Received uploads request method=POST path=/api/pending_closures15472026/10/07 09:36:39 INFO Received uploads request method=POST path=/api/pending_closures15482026/10/07 09:36:39 INFO Received cleanup request method=DELETE path=/api/pending_closures1549=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts15502026/10/07 09:36:39 INFO Received request for more parts method=POST path=/1551=== CONT TestPush_RejectsBadRequests/no_objects15522026/10/07 09:36:39 INFO Received push request method=POST path=/api/pushes1553--- PASS: TestUploadHandlersRejectOversizedBody (0.12s)1554 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)1555 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.29s)1556 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1557=== CONT TestPush_RejectsBadRequests/root_not_in_objects15582026/10/07 09:36:39 INFO Received push request method=POST path=/api/pushes1559=== CONT TestPush_RejectsBadRequests/no_roots15602026/10/07 09:36:39 INFO Received push request method=POST path=/api/pushes1561=== CONT TestPush_RejectsBadRequests/bad_root15622026/10/07 09:36:39 INFO Received push request method=POST path=/api/pushes1563=== CONT TestIsValidCachePath/narinfo1564=== CONT TestIsValidCachePath/index.html1565=== CONT TestIsValidCachePath/short_hash1566=== CONT TestIsValidCachePath/wrong_extension1567--- PASS: TestPush_RejectsBadRequests (6.00s)1568 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1569 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1570 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1571 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1572=== CONT TestIsValidCachePath/leading_slash1573=== CONT TestIsValidCachePath/empty1574=== CONT TestIsValidCachePath/random_path1575=== CONT TestIsValidCachePath/invalid_char_u1576=== CONT TestIsValidCachePath/invalid_char_e1577=== CONT TestIsValidCachePath/traversal_in_middle1578=== CONT TestIsValidCachePath/traversal_parent1579=== CONT TestIsValidCachePath/nar_uncompressed1580=== CONT TestIsValidCachePath/nix-cache-info1581=== CONT TestIsValidCachePath/realisation1582=== CONT TestIsValidCachePath/log1583=== CONT TestIsValidCachePath/ls1584=== CONT TestIsValidCachePath/nar_bz21585=== CONT TestIsValidCachePath/nar_xz1586=== CONT TestIsValidCachePath/nar_zst1587=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1588--- PASS: TestIsValidCachePath (0.03s)1589 --- PASS: TestIsValidCachePath/narinfo (0.00s)1590 --- PASS: TestIsValidCachePath/index.html (0.00s)1591 --- PASS: TestIsValidCachePath/short_hash (0.00s)1592 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1593 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1594 --- PASS: TestIsValidCachePath/empty (0.00s)1595 --- PASS: TestIsValidCachePath/random_path (0.00s)1596 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1597 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1598 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1599 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1600 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1601 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1602 --- PASS: TestIsValidCachePath/realisation (0.00s)1603 --- PASS: TestIsValidCachePath/log (0.00s)1604 --- PASS: TestIsValidCachePath/ls (0.00s)1605 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1606 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1607 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1608 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1609=== CONT TestParseSingleRange/none1610=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale16112026/10/07 09:36:40 INFO Received uploads request method=POST path=/api/pending_closures1612=== NAME TestPinProtectsFromGC1613 client_integration_test.go:731: Pinned store path: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestPinProtectsFromGC2162048575/001/store/qrbsr30w6xx2vxacmhzwa1gvk9yppnpb-pinned-file.txt1614 client_integration_test.go:732: Unpinned store path: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestPinProtectsFromGC2162048575/001/store/js875vyn8s4g5ym5jkhbfki0yrrr1675-unpinned-file.txt16152026/10/07 09:36:40 INFO Received push request method=POST path=/api/pushes16162026/10/07 09:36:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16172026/10/07 09:36:40 INFO Uploading qrbsr30w6xx2vxacmhzwa1gvk9yppnpb-pinned-file.txt (128B)16182026/10/07 09:36:40 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16192026/10/07 09:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16202026/10/07 09:36:40 WARN Failed to register uploaded object key=qrbsr30w6xx2vxacmhzwa1gvk9yppnpb.ls error="server returned 404: 404 page not found\n"16212026/10/07 09:36:40 INFO Signed narinfos id=1 count=116222026/10/07 09:36:40 INFO Uploading 1 narinfos16232026/10/07 09:36:40 INFO Received complete push request method=POST path=/api/pushes/1/complete16242026/10/07 09:36:40 WARN Failed to register uploaded object key=qrbsr30w6xx2vxacmhzwa1gvk9yppnpb.narinfo error="server returned 404: 404 page not found\n"16252026/10/07 09:36:40 INFO Received cleanup request method=DELETE path=/api/pending_closures16262026/10/07 09:36:40 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket73/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""16272026/10/07 09:36:40 INFO Aborted multipart uploads count=0 kept=116282026/10/07 09:36:40 INFO Completed push id=1 objects=3 duration=29.263709ms16292026/10/07 09:36:40 INFO Upload complete. (193ms)16302026/10/07 09:36:40 INFO Received cleanup request method=DELETE path=/api/pending_closures16312026/10/07 09:36:40 INFO Aborted multipart uploads count=1 kept=01632--- PASS: TestMultipartCleanup (9.02s)1633=== CONT TestParseSingleRange/start_far_past_EOF1634=== CONT TestParseSingleRange/start_past_EOF1635=== CONT TestParseSingleRange/single_byte1636=== CONT TestParseSingleRange/suffix_exceeds_size1637=== CONT TestParseSingleRange/suffix1638=== CONT TestParseSingleRange/end_clamped_to_size1639=== CONT TestParseSingleRange/open-ended1640=== CONT TestParseSingleRange/closed1641=== CONT TestParseSingleRange/malformed_end_before_start1642=== CONT TestParseSingleRange/malformed_both_empty1643=== CONT TestParseSingleRange/malformed_no_dash1644=== CONT TestParseSingleRange/multi-range_ignored1645=== CONT TestParseSingleRange/unknown_unit1646=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1647--- PASS: TestParseSingleRange (0.01s)1648 --- PASS: TestParseSingleRange/none (0.00s)1649 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1650 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1651 --- PASS: TestParseSingleRange/single_byte (0.00s)1652 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1653 --- PASS: TestParseSingleRange/suffix (0.00s)1654 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1655 --- PASS: TestParseSingleRange/open-ended (0.00s)1656 --- PASS: TestParseSingleRange/closed (0.00s)1657 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1658 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1659 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1660 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1661 --- PASS: TestParseSingleRange/unknown_unit (0.00s)16622026/10/07 09:36:40 INFO Received push request method=POST path=/api/pushes16632026/10/07 09:36:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16642026/10/07 09:36:40 WARN mTLS auth: subject not in bound subjects subject="CN=reader"16652026/10/07 09:36:40 INFO Uploading js875vyn8s4g5ym5jkhbfki0yrrr1675-unpinned-file.txt (128B)16662026/10/07 09:36:40 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1667--- PASS: TestService_NativeMTLS (8.71s)1668=== CONT TestGCEndsOnShutdown/before_the_run16692026/10/07 09:36:40 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16702026/10/07 09:36:40 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16712026/10/07 09:36:40 WARN Failed to register uploaded object key=js875vyn8s4g5ym5jkhbfki0yrrr1675.ls error="server returned 404: 404 page not found\n"16722026/10/07 09:36:40 INFO Signed narinfos id=2 count=116732026/10/07 09:36:40 INFO Uploading 1 narinfos16742026/10/07 09:36:40 INFO Received complete push request method=POST path=/api/pushes/2/complete16752026/10/07 09:36:40 WARN Failed to register uploaded object key=js875vyn8s4g5ym5jkhbfki0yrrr1675.narinfo error="server returned 404: 404 page not found\n"16762026/10/07 09:36:40 INFO Completed push id=2 objects=3 duration=1.001833ms16772026/10/07 09:36:40 INFO Upload complete. (128ms)16782026/10/07 09:36:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures16792026/10/07 09:36:40 INFO Garbage collection started16802026/10/07 09:36:40 INFO Aborted multipart uploads count=0 kept=016812026/10/07 09:36:40 WARN Force mode enabled - objects will be deleted immediately without grace period16822026/10/07 09:36:40 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=016832026/10/07 09:36:41 INFO Vacuumed table table=pending_closures16842026/10/07 09:36:41 INFO Received push request method=POST path=/api/pushes16852026/10/07 09:36:41 INFO Vacuumed table table=pending_objects16862026/10/07 09:36:41 INFO Vacuumed table table=multipart_uploads16872026/10/07 09:36:41 INFO Vacuumed table table=closures16882026/10/07 09:36:41 INFO Vacuumed table table=objects16892026/10/07 09:36:41 INFO Received complete push request method=POST path=/api/pushes/1/complete16902026/10/07 09:36:41 INFO Completed push id=1 objects=4 duration=19.703042ms16912026/10/07 09:36:41 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16922026/10/07 09:36:41 INFO Completed upload id=2 objects=2 duration=832.209µs1693--- PASS: TestMetricsCommit (8.75s)1694=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1695--- PASS: TestMetricsInventory (8.44s)1696=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1697=== NAME TestNARDeduplicationMetadataUploadBug1698 metadata_upload_test.go:48: First store path: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestNARDeduplicationMetadataUploadBug2563340981/001/store/mvzqs58ky40xlxfr7g8nz7s831cc28wg-file1.txt1699--- PASS: TestService_ReadScope_PublicByDefault (8.17s)1700=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1701{"timestamp":"2026-10-07T09:36:41.911952Z","level":"ERROR","duration":"36.443333ms","resp":"Response { status: 500, version: HTTP/1.1, headers: {\"content-type\": \"application/xml\"}, body: Body { once: b\"<?xml version=\\\"1.0\\\" encoding=\\\"UTF-8\\\"?><Error><Code>InternalError</Code><Message>We encountered an internal error, please try again.</Message></Error>\", remaining_limit: None } }","target":"s3s::service","filename":"/nix/var/nix/builds/nix-28079-3532540677/rustfs-1.0.0-vendor/source-registry-0/s3s-0.16.0/src/service.rs","line_number":680,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}1702{"timestamp":"2026-10-07T09:36:41.914919Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"5985d1f3-77d9-45c7-addd-8eefd524abef","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"PUT","uri":"/bucket79/","status_code":500,"suppressed_errors":0,"duration_ms":39,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":501,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}17032026/10/07 09:36:41 INFO Received push request method=POST path=/api/pushes17042026/10/07 09:36:41 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17052026/10/07 09:36:41 INFO Uploading mvzqs58ky40xlxfr7g8nz7s831cc28wg-file1.txt (160B)17062026/10/07 09:36:41 WARN Failed to register uploaded object key=mvzqs58ky40xlxfr7g8nz7s831cc28wg.ls error="server returned 404: 404 page not found\n"17072026/10/07 09:36:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17082026/10/07 09:36:41 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"17092026/10/07 09:36:41 INFO Signed narinfos id=1 count=117102026/10/07 09:36:41 INFO Uploading 1 narinfos17112026/10/07 09:36:41 INFO Received complete push request method=POST path=/api/pushes/1/complete17122026/10/07 09:36:41 WARN Failed to register uploaded object key=mvzqs58ky40xlxfr7g8nz7s831cc28wg.narinfo error="server returned 404: 404 page not found\n"17132026/10/07 09:36:42 INFO Completed push id=1 objects=3 duration=26.624459ms17142026/10/07 09:36:42 INFO Upload complete. (154ms)1715=== NAME TestNARDeduplicationMetadataUploadBug1716 metadata_upload_test.go:54: Retrieved narinfo from S3:1717 StorePath: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestNARDeduplicationMetadataUploadBug2563340981/001/store/mvzqs58ky40xlxfr7g8nz7s831cc28wg-file1.txt1718 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1719 Compression: zstd1720 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1721 NarSize: 1601722 References: 1723 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1724 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1725 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1726 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1727=== NAME TestOrphanedObjectsGCStressTest1728 orphaned_objects_gc_test.go:503: Stress test completed successfully:1729 orphaned_objects_gc_test.go:504: - Active objects preserved: 201730 orphaned_objects_gc_test.go:505: - Objects deleted: 2101731 orphaned_objects_gc_test.go:506: - Total GC'd: 2101732--- PASS: TestOrphanedObjectsGCStressTest (22.46s)1733=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1734=== NAME TestNARDeduplicationMetadataUploadBug1735 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestNARDeduplicationMetadataUploadBug2563340981/001/store/423714rjw9qqc9s9an8lavnzf0ilnv12-file2.txt17362026/10/07 09:36:42 INFO Received push request method=POST path=/api/pushes17372026/10/07 09:36:42 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17382026/10/07 09:36:42 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17392026/10/07 09:36:42 WARN Failed to register uploaded object key=423714rjw9qqc9s9an8lavnzf0ilnv12.ls error="server returned 404: 404 page not found\n"17402026/10/07 09:36:42 INFO Signed narinfos id=2 count=117412026/10/07 09:36:42 INFO Uploading 1 narinfos17422026/10/07 09:36:42 INFO Received complete push request method=POST path=/api/pushes/2/complete17432026/10/07 09:36:42 WARN Failed to register uploaded object key=423714rjw9qqc9s9an8lavnzf0ilnv12.narinfo error="server returned 404: 404 page not found\n"17442026/10/07 09:36:42 INFO Completed push id=2 objects=3 duration=681.5µs17452026/10/07 09:36:42 INFO Upload complete. (109ms)1746 metadata_upload_test.go:76: Retrieved narinfo from S3:1747 StorePath: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestNARDeduplicationMetadataUploadBug2563340981/001/store/423714rjw9qqc9s9an8lavnzf0ilnv12-file2.txt1748 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1749 Compression: zstd1750 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1751 NarSize: 1601752 References: 1753 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1754 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1755 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1756 {"version":1,"root":{"type":"regular","size":44}}1757--- PASS: TestNARDeduplicationMetadataUploadBug (9.35s)1758=== CONT TestResolveDBConnectionString/flag_wins1759=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1760=== CONT TestResolveDBConnectionString/nothing_configured1761=== CONT TestResolveDBConnectionString/missing_file_is_an_error1762=== CONT TestResolveDBConnectionString/file_when_flag_empty1763=== CONT TestServerTLSConfig/no_client_CA1764=== CONT TestServerTLSConfig/missing_CA_file1765=== CONT TestServerTLSConfig/not_a_PEM_file1766--- PASS: TestResolveDBConnectionString (0.03s)1767 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1768 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1769 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1770 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1771 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1772--- PASS: TestServerTLSConfig (0.01s)1773 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1774 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1775 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)1776=== CONT TestClientErrorHandling/InvalidStorePath17772026/10/07 09:36:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=017782026/10/07 09:36:42 INFO Received create pin request method=POST path=/api/pins/myapp17792026/10/07 09:36:42 INFO Created/updated pin name=myapp store_path=/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestPinProtectsFromGC2162048575/001/store/qrbsr30w6xx2vxacmhzwa1gvk9yppnpb-pinned-file.txt narinfo_key=qrbsr30w6xx2vxacmhzwa1gvk9yppnpb.narinfo17802026/10/07 09:36:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures17812026/10/07 09:36:42 INFO Garbage collection started17822026/10/07 09:36:42 INFO Aborted multipart uploads count=0 kept=017832026/10/07 09:36:42 WARN Force mode enabled - objects will be deleted immediately without grace period17842026/10/07 09:36:42 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=017852026/10/07 09:36:42 INFO Vacuumed table table=pending_closures17862026/10/07 09:36:42 INFO Vacuumed table table=pending_objects17872026/10/07 09:36:42 INFO Vacuumed table table=multipart_uploads17882026/10/07 09:36:42 INFO Vacuumed table table=closures17892026/10/07 09:36:42 INFO Vacuumed table table=objects1790=== NAME TestClientCADerivations1791 client_ca_test.go:136: Built CA derivation: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientCADerivations3617665967/001/store/b8vdv4zsb3dmplg2ipx7v945mpyk3y4l-ca-test1792--- PASS: TestCacheStatsHandler (7.92s)1793=== CONT TestClientErrorHandling/ServerNotAvailable1794=== NAME TestClientCADerivations1795 client_ca_test.go:139: Found 1 dependencies (including self)1796=== NAME TestClientWithDependencies1797 client_integration_test.go:613: Built derivation: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientWithDependencies1429172932/001/store/w7jja47mmrr502wsrkhjs8rr329hs0zy-test-script1798--- PASS: TestDeleteClosuresRacingPins (12.82s)17992026/10/07 09:36:43 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/present1800=== CONT TestClientErrorHandling/InvalidAuthToken18012026/10/07 09:36:43 INFO Received push request method=POST path=/api/pushes18022026/10/07 09:36:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18032026/10/07 09:36:43 INFO Uploading b8vdv4zsb3dmplg2ipx7v945mpyk3y4l-ca-test (144B)1804=== NAME TestClientWithDependencies1805 client_integration_test.go:615: Found 1 dependencies (including self)18062026/10/07 09:36:43 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18072026/10/07 09:36:43 WARN Failed to register uploaded object key=b8vdv4zsb3dmplg2ipx7v945mpyk3y4l.ls error="server returned 404: 404 page not found\n"18082026/10/07 09:36:43 WARN Failed to register uploaded object key=log/ayw1kfbxky6wgfqqv8lpw9xxlga98swr-ca-test.drv error="server returned 404: 404 page not found\n"18092026/10/07 09:36:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18102026/10/07 09:36:43 INFO Signed narinfos id=1 count=118112026/10/07 09:36:43 INFO Uploading 1 narinfos18122026/10/07 09:36:43 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=193.189229ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18132026/10/07 09:36:43 INFO Received complete push request method=POST path=/api/pushes/1/complete18142026/10/07 09:36:43 WARN Failed to register uploaded object key=b8vdv4zsb3dmplg2ipx7v945mpyk3y4l.narinfo error="server returned 404: 404 page not found\n"18152026/10/07 09:36:43 INFO Received push request method=POST path=/api/pushes18162026/10/07 09:36:43 INFO Completed push id=1 objects=4 duration=36.468708ms18172026/10/07 09:36:43 INFO Upload complete. (327ms)1818=== NAME TestClientCADerivations1819 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientCADerivations3617665967/001/store/b8vdv4zsb3dmplg2ipx7v945mpyk3y4l-ca-test1820 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1821 Compression: zstd1822 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1823 NarSize: 1441824 References: 1825 Deriver: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientCADerivations3617665967/001/store/ayw1kfbxky6wgfqqv8lpw9xxlga98swr-ca-test.drv1826 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1827 client_ca_test.go:185: Checking for realisation files in S3...1828 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1829 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache18302026/10/07 09:36:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18312026/10/07 09:36:43 INFO Uploading w7jja47mmrr502wsrkhjs8rr329hs0zy-test-script (136B)18322026/10/07 09:36:43 WARN Failed to register uploaded object key=w7jja47mmrr502wsrkhjs8rr329hs0zy.ls error="server returned 404: 404 page not found\n"18332026/10/07 09:36:43 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18342026/10/07 09:36:43 WARN Failed to register uploaded object key=log/j376804jbc3s06vr4spf92nxr8hy4vw6-test-script.drv error="server returned 404: 404 page not found\n"18352026/10/07 09:36:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18362026/10/07 09:36:43 INFO Signed narinfos id=1 count=118372026/10/07 09:36:43 INFO Uploading 1 narinfos18382026/10/07 09:36:43 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=402.805577ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18392026/10/07 09:36:43 INFO Received complete push request method=POST path=/api/pushes/1/complete18402026/10/07 09:36:43 WARN Failed to register uploaded object key=w7jja47mmrr502wsrkhjs8rr329hs0zy.narinfo error="server returned 404: 404 page not found\n"18412026/10/07 09:36:43 INFO Completed push id=1 objects=4 duration=50.081041ms18422026/10/07 09:36:43 INFO Upload complete. (273ms)1843=== NAME TestClientWithDependencies1844 client_integration_test.go:617: Skipping nix copy test - isolated store (/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientWithDependencies1429172932/001/store) requires matching store prefix1845=== NAME TestClientCADerivations1846 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket79?endpoint=http://localhost:58681®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientCADerivations3617665967/001/store'1847 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11848--- PASS: TestService_ReadAuthMiddleware (7.92s)1849=== CONT TestCacheConfigHandler/full_config,_no_issuer1850=== CONT TestCacheConfigHandler/no_signing_keys1851=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1852=== CONT TestCacheConfigHandler/no_cache_url_configured1853--- PASS: TestCacheConfigHandler (0.01s)1854 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1855 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1856 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1857 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1858--- PASS: TestClientWithDependencies (8.51s)1859--- PASS: TestClientCADerivations (9.56s)18602026/10/07 09:36:43 INFO Received push request method=POST path=/api/pushes18612026-10-07 09:36:43.920 UTC [92167] LOG: checkpoint starting: wal18622026/10/07 09:36:43 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=803.199508ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18632026/10/07 09:36:43 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)18642026/10/07 09:36:43 INFO Uploading hmkzsvfbrfm0bzlywkcbqjd3yq2x0all-shared-dep (136B)18652026/10/07 09:36:43 INFO Uploading 6kx61gi9ca4787j5gvrpdv2nd8wxwrq6-top (264B)18662026/10/07 09:36:44 WARN Failed to register uploaded object key=hmkzsvfbrfm0bzlywkcbqjd3yq2x0all.ls error="server returned 404: 404 page not found\n"18672026/10/07 09:36:44 WARN Failed to register uploaded object key=nar/0irl8cq9hpmmfpgwjyl6ayg8rmzs4ngwb49i2znqkqfz8f9p0ixr.nar.zst error="server returned 404: 404 page not found\n"18682026/10/07 09:36:44 WARN Failed to register uploaded object key=6kx61gi9ca4787j5gvrpdv2nd8wxwrq6.ls error="server returned 404: 404 page not found\n"18692026/10/07 09:36:44 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18702026/10/07 09:36:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18712026/10/07 09:36:44 INFO Signed narinfos id=1 count=218722026/10/07 09:36:44 INFO Uploading 2 narinfos1873=== RUN TestService_RequireScope_OIDC/builder_may_write1874=== PAUSE TestService_RequireScope_OIDC/builder_may_write1875=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1876=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1877=== RUN TestService_RequireScope_OIDC/ops_may_admin1878=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1879=== RUN TestService_RequireScope_OIDC/ops_may_not_write1880=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1881=== RUN TestService_RequireScope_OIDC/reader_may_not_write1882=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1883=== RUN TestService_RequireScope_OIDC/static_token_may_admin1884=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1885=== RUN TestService_RequireScope_OIDC/static_token_may_write1886=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1887=== RUN TestService_RequireScope_OIDC/reader_may_read1888=== PAUSE TestService_RequireScope_OIDC/reader_may_read1889=== RUN TestService_RequireScope_OIDC/writer_implies_read1890=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1891=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1892=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1893=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1894=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1895=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1896=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1897=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1898=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1899=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1900=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1901=== CONT TestService_RequireScope_OIDC/builder_may_write1902=== CONT TestService_RequireScope_OIDC/reader_may_read1903=== CONT TestService_RequireScope_OIDC/reader_may_not_write1904=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1905=== CONT TestService_RequireScope_OIDC/ops_may_admin1906=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19072026/10/07 09:36:44 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]1908=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1909=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1910=== CONT TestService_RequireScope_OIDC/writer_implies_read19112026/10/07 09:36:44 WARN Failed to register uploaded object key=6kx61gi9ca4787j5gvrpdv2nd8wxwrq6.narinfo error="server returned 404: 404 page not found\n"1912=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1913=== CONT TestService_RequireScope_OIDC/ops_may_not_write1914=== CONT TestService_RequireScope_OIDC/static_token_may_write1915=== CONT TestService_RequireScope_OIDC/static_token_may_admin1916=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc19172026/10/07 09:36:44 INFO Received complete push request method=POST path=/api/pushes/1/complete19182026/10/07 09:36:44 WARN Failed to register uploaded object key=hmkzsvfbrfm0bzlywkcbqjd3yq2x0all.narinfo error="server returned 404: 404 page not found\n"1919--- PASS: TestService_RequireScope_OIDC (7.32s)1920 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1921 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1922 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1923 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1924 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1925 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.01s)1926 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1927 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1928 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1929 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1930 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1931 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1932 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1933 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)19342026/10/07 09:36:44 INFO Completed push id=1 objects=6 duration=27.644791ms19352026/10/07 09:36:44 INFO Upload complete. (288ms)1936=== NAME TestClientSharedPathCommittedMidPush1937 client_integration_test.go:680: Retrieved narinfo from S3:1938 StorePath: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientSharedPathCommittedMidPush376782034/001/store/hmkzsvfbrfm0bzlywkcbqjd3yq2x0all-shared-dep1939 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1940 Compression: zstd1941 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821942 NarSize: 1361943 References: 1944 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1945 client_integration_test.go:680: Retrieved narinfo from S3:1946 StorePath: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientSharedPathCommittedMidPush376782034/001/store/6kx61gi9ca4787j5gvrpdv2nd8wxwrq6-top1947 URL: nar/0irl8cq9hpmmfpgwjyl6ayg8rmzs4ngwb49i2znqkqfz8f9p0ixr.nar.zst1948 Compression: zstd1949 NarHash: sha256:0irl8cq9hpmmfpgwjyl6ayg8rmzs4ngwb49i2znqkqfz8f9p0ixr1950 NarSize: 2641951 References: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientSharedPathCommittedMidPush376782034/001/store/hmkzsvfbrfm0bzlywkcbqjd3yq2x0all-shared-dep1952 CA: text:sha256:1f4rgbr0jfkg9jza9pwkfgdx17mc76cr73p374brjcc4lbnvyrjg1953--- PASS: TestClientSharedPathCommittedMidPush (8.32s)1954=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1955=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1956=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1957=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1958=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1959=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1960=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1961=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1962=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1963=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19642026/10/07 09:36:44 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]1965=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1966=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19672026/10/07 09:36:44 WARN Authentication failed token_preview=eyJhbGciOi...JY_Iokg2Sg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1968--- PASS: TestService_AuthMiddleware_OIDC (7.28s)1969 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)1970 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1971 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1972 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)19732026/10/07 09:36:44 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19742026/10/07 09:36:44 WARN mTLS auth: bound subjects configured but subject DN unavailable19752026/10/07 09:36:44 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"19762026/10/07 09:36:44 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.71975147s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1977--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (7.45s)1978=== NAME TestPinProtectsFromGC1979 client_integration_test.go:840: Pin successfully protected closure from garbage collection1980--- PASS: TestPinProtectsFromGC (14.06s)1981--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (7.00s)1982{"timestamp":"2026-10-07T09:36:45.029029Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":6,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(7)"}1983--- PASS: TestService_healthCheckHandler (6.68s)19842026/10/07 09:36:45 WARN readiness check failed error="closed pool"1985--- PASS: TestService_readinessHandler (7.28s)19862026/10/07 09:36:45 INFO Aborted multipart uploads count=1 kept=019872026/10/07 09:36:45 INFO Received cleanup request method=DELETE path=/api/pending_closures19882026/10/07 09:36:45 INFO Aborted multipart uploads count=1 kept=01989--- PASS: TestPendingCleanupUsesOneCutoff (15.38s)19902026/10/07 09:36:46 INFO Received uploads request method=POST path=/api/pending_closures1991=== NAME TestClientMultipleUploads1992 client_integration_test.go:358: Created store path 0: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientMultipleUploads2551477243/001/store/razffb7pfxhki1nxv1fx6p5kjrgripnc-test-file-0.txt1993 client_integration_test.go:358: Created store path 1: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientMultipleUploads2551477243/001/store/qbf8fwhiy2h3ziqx5nwv1dz1vdsjbmq7-test-file-1.txt1994 client_integration_test.go:358: Created store path 2: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestClientMultipleUploads2551477243/001/store/5dlcbfa6a8948vqgplhrn7ix88w9kmpx-test-file-2.txt19952026/10/07 09:36:46 INFO Received push request method=POST path=/api/pushes19962026/10/07 09:36:46 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)19972026/10/07 09:36:46 INFO Uploading razffb7pfxhki1nxv1fx6p5kjrgripnc-test-file-0.txt (160B)19982026/10/07 09:36:46 INFO Uploading qbf8fwhiy2h3ziqx5nwv1dz1vdsjbmq7-test-file-1.txt (160B)19992026/10/07 09:36:46 INFO Uploading 5dlcbfa6a8948vqgplhrn7ix88w9kmpx-test-file-2.txt (160B)20002026/10/07 09:36:46 WARN Failed to register uploaded object key=razffb7pfxhki1nxv1fx6p5kjrgripnc.ls error="server returned 404: 404 page not found\n"20012026/10/07 09:36:46 WARN Failed to register uploaded object key=5dlcbfa6a8948vqgplhrn7ix88w9kmpx.ls error="server returned 404: 404 page not found\n"20022026/10/07 09:36:46 WARN Failed to register uploaded object key=qbf8fwhiy2h3ziqx5nwv1dz1vdsjbmq7.ls error="server returned 404: 404 page not found\n"20032026/10/07 09:36:46 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"20042026/10/07 09:36:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20052026/10/07 09:36:46 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"20062026/10/07 09:36:46 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"20072026/10/07 09:36:46 INFO Signed narinfos id=1 count=320082026/10/07 09:36:46 INFO Uploading 3 narinfos20092026/10/07 09:36:46 WARN Failed to register uploaded object key=qbf8fwhiy2h3ziqx5nwv1dz1vdsjbmq7.narinfo error="server returned 404: 404 page not found\n"20102026/10/07 09:36:46 INFO Received complete push request method=POST path=/api/pushes/1/complete20112026/10/07 09:36:46 WARN Failed to register uploaded object key=razffb7pfxhki1nxv1fx6p5kjrgripnc.narinfo error="server returned 404: 404 page not found\n"20122026/10/07 09:36:46 WARN Failed to register uploaded object key=5dlcbfa6a8948vqgplhrn7ix88w9kmpx.narinfo error="server returned 404: 404 page not found\n"20132026/10/07 09:36:46 INFO Completed push id=1 objects=9 duration=20.829584ms20142026/10/07 09:36:46 INFO Upload complete. (137ms)2015 client_integration_test.go:369: Uploaded 3 paths in 169.979833ms2016--- PASS: TestClientMultipleUploads (7.66s)20172026/10/07 09:36:46 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-config20182026/10/07 09:36:46 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=214.331001ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20192026/10/07 09:36:46 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=364.329905ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2020--- PASS: TestPendingClosureWriteTimeout (0.00s)2021 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2022 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2023 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2024 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (7.46s)20252026/10/07 09:36:46 INFO Aborted multipart uploads count=0 kept=020262026/10/07 09:36:46 WARN Force mode enabled - objects will be deleted immediately without grace period20272026-10-07 09:36:46.974 UTC [92667] ERROR: canceling statement due to user request20282026-10-07 09:36:46.974 UTC [92667] CONTEXT: SQL statement "UPDATE object_stats s2029 SET object_count = s.object_count + n.n - o.n,2030 total_bytes = s.total_bytes + n.bytes - o.bytes2031 FROM (2032 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes2033 FROM new_rows WHERE deleted_at IS NULL2034 ) AS n,2035 (2036 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes2037 FROM old_rows WHERE deleted_at IS NULL2038 ) AS o2039 WHERE s.id AND (n.n <> o.n OR n.bytes <> o.bytes)"2040 PL/pgSQL function object_stats_update() line 3 at SQL statement20412026-10-07 09:36:46.974 UTC [92667] STATEMENT: -- name: MarkStaleObjects :execrows2042 WITH RECURSIVE ct AS (2043 SELECT timezone('UTC', now()) AS now2044 ),2045 closure_reach AS (2046 -- Start with all closure keys2047 SELECT o.key, o.refs2048 FROM objects o2049 INNER JOIN closures c ON o.key = c.key2050 UNION2051 -- Recursively add all referenced objects2052 SELECT o.key, o.refs2053 FROM objects o2054 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2055 ),2056 reachable_objects AS (2057 SELECT DISTINCT key FROM closure_reach2058 ),2059 stale_objects AS (2060 SELECT o.key2061 FROM objects AS o, ct2062 WHERE2063 NOT EXISTS (2064 SELECT 12065 FROM reachable_objects ro2066 WHERE ro.key = o.key2067 )2068 AND NOT EXISTS (2069 SELECT 12070 FROM pending_objects AS po2071 WHERE po.key = o.key2072 )2073 AND o.deleted_at IS NULL -- Only mark fresh objects2074 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2075 FOR UPDATE2076 )2077 UPDATE objects2078 SET2079 deleted_at = ct.now,2080 first_deleted_at = COALESCE(first_deleted_at, ct.now)2081 FROM stale_objects, ct2082 WHERE objects.key = stale_objects.key2083 20842026/10/07 09:36:47 INFO Aborted multipart uploads count=0 kept=020852026/10/07 09:36:47 WARN Force mode enabled - objects will be deleted immediately without grace period20862026/10/07 09:36:47 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:58681/bucket96/?delete=\": context canceled"2087--- PASS: TestGCEndsOnShutdown (0.00s)2088 --- PASS: TestGCEndsOnShutdown/before_the_run (5.77s)2089 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (5.79s)2090 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (5.77s)2091--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2092 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (6.84s)2093 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (6.52s)20942026/10/07 09:36:47 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=824.849724ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20952026/10/07 09:36:47 INFO Received uploads request method=POST path=/api/pending_closures20962026/10/07 09:36:47 INFO Aborted multipart uploads count=0 kept=020972026/10/07 09:36:47 WARN Force mode enabled - objects will be deleted immediately without grace period20982026/10/07 09:36:47 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=020992026/10/07 09:36:47 INFO Vacuumed table table=pending_closures21002026/10/07 09:36:47 INFO Vacuumed table table=pending_objects21012026/10/07 09:36:47 INFO Vacuumed table table=multipart_uploads21022026/10/07 09:36:47 INFO Vacuumed table table=closures21032026/10/07 09:36:47 INFO Vacuumed table table=objects21042026/10/07 09:36:47 INFO Received uploads request method=POST path=/api/pending_closures21052026/10/07 09:36:47 INFO Aborted multipart uploads count=0 kept=021062026/10/07 09:36:47 WARN Force mode enabled - objects will be deleted immediately without grace period21072026/10/07 09:36:47 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=021082026/10/07 09:36:47 INFO Vacuumed table table=pending_closures21092026/10/07 09:36:47 INFO Vacuumed table table=pending_objects21102026/10/07 09:36:47 INFO Vacuumed table table=multipart_uploads21112026/10/07 09:36:47 INFO Vacuumed table table=closures21122026/10/07 09:36:47 INFO Vacuumed table table=objects2113--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2114 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (5.68s)2115 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (5.76s)21162026/10/07 09:36:48 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.484008587s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21172026/10/07 09:36:48 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21182026/10/07 09:36:48 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21192026/10/07 09:36:49 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"21202026/10/07 09:36:49 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-config21212026/10/07 09:36:49 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=193.814795ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21222026/10/07 09:36:49 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=360.287768ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21232026/10/07 09:36:50 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=724.468485ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21242026/10/07 09:36:50 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.518675361s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2125{"timestamp":"2026-10-07T09:36:51.94182Z","level":"ERROR","message":"Scanner cycle completed without a durable data usage snapshot","event":"scanner_persist_state","component":"scanner","subsystem":"runtime","cycle":6,"outcome":"NoUpdate","state":"usage_not_durable","target":"rustfs::scanner","filename":"crates/scanner/src/scanner.rs","line_number":2350,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}21262026/10/07 09:36:52 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_closures21272026/10/07 09:36:52 WARN Request failed, retrying attempt=2 max_attempts=6 backoff=180.145215ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21282026/10/07 09:36:52 WARN Request failed, retrying attempt=3 max_attempts=6 backoff=364.681341ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21292026/10/07 09:36:53 WARN Request failed, retrying attempt=4 max_attempts=6 backoff=815.336585ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21302026/10/07 09:36:53 WARN Request failed, retrying attempt=5 max_attempts=6 backoff=1.567608065s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2131--- PASS: TestClientErrorHandling (0.00s)2132 --- PASS: TestClientErrorHandling/InvalidStorePath (5.49s)2133 --- PASS: TestClientErrorHandling/InvalidAuthToken (5.03s)2134 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.51s)2135PASS21362026-10-07 09:36:55.734 UTC [92162] LOG: received smart shutdown request21372026-10-07 09:36:55.735 UTC [92162] LOG: background worker "logical replication launcher" (PID 92173) exited with exit code 121382026-10-07 09:36:57.045 UTC [92167] LOG: checkpoint complete: wrote 10649 buffers (65.0%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=12.267 s, sync=0.699 s, total=13.126 s; sync files=34045, longest=0.001 s, average=0.001 s; distance=533508 kB, estimate=533508 kB; lsn=0/227C2060, redo lsn=0/2208E12021392026-10-07 09:36:57.046 UTC [92167] LOG: shutting down21402026-10-07 09:36:57.046 UTC [92167] LOG: checkpoint starting: shutdown immediate21412026-10-07 09:36:57.104 UTC [92167] LOG: checkpoint complete: wrote 1287 buffers (7.9%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.044 s, sync=0.008 s, total=0.059 s; sync files=472, longest=0.001 s, average=0.001 s; distance=7375 kB, estimate=480895 kB; lsn=0/227C20D8, redo lsn=0/227C20D821422026-10-07 09:36:57.110 UTC [92162] LOG: database system is shut down2143Running OIDC tests...2144=== RUN TestAudienceForIssuer2145=== PAUSE TestAudienceForIssuer2146=== RUN TestGlobMatch2147=== PAUSE TestGlobMatch2148=== RUN TestValidateToken_ValidToken2149=== PAUSE TestValidateToken_ValidToken2150=== RUN TestValidateToken_WrongAudience2151=== PAUSE TestValidateToken_WrongAudience2152=== RUN TestValidateToken_Expired2153=== PAUSE TestValidateToken_Expired2154=== RUN TestValidateToken_BoundClaimsMismatch2155=== PAUSE TestValidateToken_BoundClaimsMismatch2156=== RUN TestValidateToken_BoundSubjectMismatch2157=== PAUSE TestValidateToken_BoundSubjectMismatch2158=== RUN TestValidateToken_MultipleProviders2159=== PAUSE TestValidateToken_MultipleProviders2160=== RUN TestValidateToken_NoMatchingProvider2161=== PAUSE TestValidateToken_NoMatchingProvider2162=== RUN TestValidateToken_KubernetesServiceAccount2163=== PAUSE TestValidateToken_KubernetesServiceAccount2164=== RUN TestNewValidator_KubernetesRequiresCA2165=== PAUSE TestNewValidator_KubernetesRequiresCA2166=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2167=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2168=== RUN TestPins_ReservedForMatchingRule2169=== PAUSE TestPins_ReservedForMatchingRule2170=== RUN TestPins_TopLevelShorthand2171=== PAUSE TestPins_TopLevelShorthand2172=== RUN TestPins_ConfigValidation2173=== PAUSE TestPins_ConfigValidation2174=== RUN TestScopes_LegacyProviderDefaultsToWrite2175=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2176=== RUN TestScopes_Rules2177=== PAUSE TestScopes_Rules2178=== RUN TestScopes_ConfigValidation2179=== PAUSE TestScopes_ConfigValidation2180=== CONT TestAudienceForIssuer2181=== CONT TestValidateToken_KubernetesServiceAccount2182=== CONT TestValidateToken_BoundClaimsMismatch2183=== CONT TestPins_ConfigValidation2184--- PASS: TestAudienceForIssuer (0.00s)2185=== CONT TestValidateToken_Expired2186=== CONT TestValidateToken_WrongAudience2187=== CONT TestValidateToken_ValidToken2188=== CONT TestGlobMatch2189=== RUN TestGlobMatch/foo_foo2190=== PAUSE TestGlobMatch/foo_foo2191=== RUN TestGlobMatch/foo_bar2192=== PAUSE TestGlobMatch/foo_bar2193=== RUN TestGlobMatch/*_2194=== PAUSE TestGlobMatch/*_2195=== RUN TestGlobMatch/*_anything2196=== PAUSE TestGlobMatch/*_anything2197=== RUN TestGlobMatch/foo*_foo2198=== PAUSE TestGlobMatch/foo*_foo2199=== RUN TestGlobMatch/foo*_foobar2200=== PAUSE TestGlobMatch/foo*_foobar2201=== RUN TestGlobMatch/foo*_bar2202=== PAUSE TestGlobMatch/foo*_bar2203=== RUN TestGlobMatch/*bar_bar2204=== PAUSE TestGlobMatch/*bar_bar2205=== RUN TestGlobMatch/*bar_foobar2206=== PAUSE TestGlobMatch/*bar_foobar2207=== RUN TestGlobMatch/*bar_foo2208=== PAUSE TestGlobMatch/*bar_foo2209=== RUN TestGlobMatch/foo*bar_foobar2210=== PAUSE TestGlobMatch/foo*bar_foobar2211=== RUN TestGlobMatch/foo*bar_foo123bar2212=== PAUSE TestGlobMatch/foo*bar_foo123bar2213=== RUN TestGlobMatch/foo*bar_foobarbaz2214=== PAUSE TestGlobMatch/foo*bar_foobarbaz2215=== RUN TestGlobMatch/*/*_foo/bar2216=== PAUSE TestGlobMatch/*/*_foo/bar2217=== RUN TestGlobMatch/*/*_foo2218=== PAUSE TestGlobMatch/*/*_foo2219=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2220=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2221=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02222=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02223=== RUN TestGlobMatch/refs/*/main_refs/heads/main2224=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2225=== RUN TestGlobMatch/fo?_foo2226=== PAUSE TestGlobMatch/fo?_foo2227=== RUN TestGlobMatch/fo?_fo2228=== PAUSE TestGlobMatch/fo?_fo2229=== RUN TestGlobMatch/fo?_fooo2230=== PAUSE TestGlobMatch/fo?_fooo2231=== RUN TestGlobMatch/?oo_foo2232=== PAUSE TestGlobMatch/?oo_foo2233=== RUN TestGlobMatch/?oo_boo2234=== PAUSE TestGlobMatch/?oo_boo2235=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2236=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2237=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2238=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2239=== CONT TestGlobMatch/foo_foo2240=== CONT TestValidateToken_MultipleProviders2241=== CONT TestGlobMatch/*/*_foo/bar2242=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2243=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2244=== CONT TestGlobMatch/?oo_boo2245=== CONT TestGlobMatch/?oo_foo2246=== CONT TestGlobMatch/fo?_fooo2247=== CONT TestGlobMatch/fo?_fo2248=== CONT TestGlobMatch/fo?_foo2249=== CONT TestGlobMatch/refs/*/main_refs/heads/main2250=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02251=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2252=== CONT TestGlobMatch/*/*_foo2253=== CONT TestGlobMatch/*bar_bar2254=== CONT TestGlobMatch/foo*bar_foobarbaz2255=== CONT TestGlobMatch/foo*bar_foo123bar2256=== CONT TestGlobMatch/foo*bar_foobar2257=== CONT TestGlobMatch/*bar_foo2258=== CONT TestGlobMatch/*bar_foobar2259=== CONT TestGlobMatch/foo*_foo2260=== CONT TestGlobMatch/foo*_bar2261=== CONT TestGlobMatch/foo*_foobar2262=== CONT TestGlobMatch/*_2263=== CONT TestGlobMatch/*_anything2264=== CONT TestGlobMatch/foo_bar2265--- PASS: TestGlobMatch (0.00s)2266 --- PASS: TestGlobMatch/foo_foo (0.00s)2267 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2268 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2269 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2270 --- PASS: TestGlobMatch/?oo_boo (0.00s)2271 --- PASS: TestGlobMatch/?oo_foo (0.00s)2272 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2273 --- PASS: TestGlobMatch/fo?_fo (0.00s)2274 --- PASS: TestGlobMatch/fo?_foo (0.00s)2275 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2276 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2277 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2278 --- PASS: TestGlobMatch/*/*_foo (0.00s)2279 --- PASS: TestGlobMatch/*bar_bar (0.00s)2280 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2281 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2282 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2283 --- PASS: TestGlobMatch/*bar_foo (0.00s)2284 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2285 --- PASS: TestGlobMatch/foo*_foo (0.00s)2286 --- PASS: TestGlobMatch/foo*_bar (0.00s)2287 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2288 --- PASS: TestGlobMatch/*_ (0.00s)2289 --- PASS: TestGlobMatch/*_anything (0.00s)2290 --- PASS: TestGlobMatch/foo_bar (0.00s)2291=== CONT TestValidateToken_NoMatchingProvider2292--- PASS: TestPins_ConfigValidation (0.01s)2293=== CONT TestPins_ReservedForMatchingRule2294=== CONT TestPins_TopLevelShorthand2295=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2296=== CONT TestNewValidator_KubernetesRequiresCA2297=== CONT TestScopes_Rules2298=== CONT TestScopes_ConfigValidation2299=== CONT TestValidateToken_BoundSubjectMismatch2300--- PASS: TestScopes_ConfigValidation (0.00s)2301=== CONT TestScopes_LegacyProviderDefaultsToWrite23022026/10/07 09:36:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59177/oidc2303--- PASS: TestValidateToken_Expired (0.05s)23042026/10/07 09:36:59 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323052026/10/07 09:36:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59180/oidc2306--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.06s)2307--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.05s)23082026/10/07 09:36:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59183/oidc23092026/10/07 09:36:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59185/oidc2310--- PASS: TestPins_TopLevelShorthand (0.07s)2311--- PASS: TestScopes_Rules (0.07s)23122026/10/07 09:36:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59188/oidc2313--- PASS: TestValidateToken_BoundClaimsMismatch (0.09s)23142026/10/07 09:36:59 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5919023152026/10/07 09:36:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59192/oidc23162026/10/07 09:36:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59194/oidc2317--- PASS: TestPins_ReservedForMatchingRule (0.08s)2318--- PASS: TestValidateToken_KubernetesServiceAccount (0.09s)2319--- PASS: TestValidateToken_BoundSubjectMismatch (0.08s)23202026/10/07 09:36:59 http: TLS handshake error from 127.0.0.1:59197: remote error: tls: bad certificate2321--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)23222026/10/07 09:36:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59199/oidc2323--- PASS: TestValidateToken_ValidToken (0.10s)23242026/10/07 09:36:59 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:59203/oidc2325--- PASS: TestValidateToken_WrongAudience (0.14s)23262026/10/07 09:36:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:59201/oidc23272026/10/07 09:36:59 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:59205/oidc2328--- PASS: TestValidateToken_MultipleProviders (0.21s)23292026/10/07 09:36:59 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:59202/oidc2330--- PASS: TestValidateToken_NoMatchingProvider (0.23s)2331PASS2332Running hook tests...2333=== RUN TestSendPathsEmpty2334=== PAUSE TestSendPathsEmpty2335=== RUN TestQueueEnqueueAndFetch2336=== PAUSE TestQueueEnqueueAndFetch2337=== RUN TestQueueDeduplication2338=== PAUSE TestQueueDeduplication2339=== RUN TestQueueRemove2340=== PAUSE TestQueueRemove2341=== RUN TestQueueFetchBatchLimit2342=== PAUSE TestQueueFetchBatchLimit2343=== RUN TestQueueRetryMovesToBack2344=== PAUSE TestQueueRetryMovesToBack2345=== RUN TestQueueFetchRemoveLifecycle2346=== PAUSE TestQueueFetchRemoveLifecycle2347=== RUN TestQueueConcurrentWriters2348=== PAUSE TestQueueConcurrentWriters2349=== RUN TestQueueRemoveLargeClosure2350=== PAUSE TestQueueRemoveLargeClosure2351=== RUN TestServerClientIntegration2352--- PASS: TestServerClientIntegration (0.00s)2353=== RUN TestServerQueueError23542026/10/07 09:36:59 ERROR Failed to queue paths error="permission denied" count=12355--- PASS: TestServerQueueError (0.00s)2356=== RUN TestGetListenerSocketActivation2357 server_test.go:146: systemd socket activation does not exist on darwin2358--- SKIP: TestGetListenerSocketActivation (0.00s)2359=== RUN TestDrainIsolatesPoisonPath2360=== PAUSE TestDrainIsolatesPoisonPath2361=== RUN TestRunNotBlockedByPoisonHead2362=== PAUSE TestRunNotBlockedByPoisonHead2363=== RUN TestDrainGivesUpWhenServerDown2364=== PAUSE TestDrainGivesUpWhenServerDown2365=== RUN TestFailedPathPrunedByLaterClosure2366=== PAUSE TestFailedPathPrunedByLaterClosure2367=== RUN TestWorkerUploadsAndRemoves2368=== PAUSE TestWorkerUploadsAndRemoves2369=== RUN TestWorkerSkipsGCdPaths2370=== PAUSE TestWorkerSkipsGCdPaths2371=== RUN TestWorkerPrunesClosureDeps2372=== PAUSE TestWorkerPrunesClosureDeps2373=== RUN TestDrainTimeout2374=== PAUSE TestDrainTimeout2375=== CONT TestSendPathsEmpty2376=== CONT TestDrainIsolatesPoisonPath2377--- PASS: TestSendPathsEmpty (0.00s)2378=== CONT TestQueueRemoveLargeClosure2379=== CONT TestQueueConcurrentWriters2380=== CONT TestQueueFetchRemoveLifecycle2381=== CONT TestQueueRetryMovesToBack2382=== CONT TestQueueFetchBatchLimit2383=== CONT TestQueueRemove2384=== CONT TestQueueDeduplication2385=== CONT TestQueueEnqueueAndFetch2386=== CONT TestWorkerPrunesClosureDeps2387=== CONT TestDrainTimeout2388=== CONT TestWorkerSkipsGCdPaths2389=== CONT TestWorkerUploadsAndRemoves2390=== CONT TestDrainGivesUpWhenServerDown2391=== CONT TestRunNotBlockedByPoisonHead2392=== CONT TestFailedPathPrunedByLaterClosure23932026/10/07 09:36:59 INFO Upload queue status pending=323942026/10/07 09:36:59 INFO Uploading batch count=123952026/10/07 09:36:59 ERROR Upload failed error="upload failed" count=123962026/10/07 09:36:59 INFO Upload queue status pending=223972026/10/07 09:36:59 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestWorkerSkipsGCdPaths200441574/002/nonexistent2398--- PASS: TestQueueFetchRemoveLifecycle (0.01s)23992026/10/07 09:36:59 INFO Uploading batch count=124002026/10/07 09:36:59 INFO Uploading batch count=124012026/10/07 09:36:59 ERROR Upload failed error="upload failed" count=12402--- PASS: TestQueueFetchBatchLimit (0.01s)24032026/10/07 09:36:59 INFO Uploading batch count=424042026/10/07 09:36:59 ERROR Upload failed error="upload failed" count=424052026/10/07 09:36:59 INFO Upload queue status pending=224062026/10/07 09:36:59 INFO Uploading batch count=224072026/10/07 09:36:59 INFO Upload queue status pending=224082026/10/07 09:36:59 INFO Uploading batch count=22409--- PASS: TestQueueEnqueueAndFetch (0.01s)24102026/10/07 09:36:59 ERROR Upload failed error="upload failed" count=224112026/10/07 09:36:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestDrainGivesUpWhenServerDown804517098/002/a24122026/10/07 09:36:59 INFO Uploading batch count=224132026/10/07 09:36:59 INFO Uploading batch count=124142026/10/07 09:36:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestDrainGivesUpWhenServerDown804517098/002/b24152026/10/07 09:36:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestDrainIsolatesPoisonPath1665412836/002/bbb24162026/10/07 09:36:59 INFO Uploading batch count=12417--- PASS: TestQueueDeduplication (0.01s)24182026/10/07 09:36:59 INFO Uploading batch count=224192026/10/07 09:36:59 ERROR Upload failed error="upload failed" count=224202026/10/07 09:36:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestDrainGivesUpWhenServerDown804517098/002/c24212026/10/07 09:36:59 INFO Uploading batch count=124222026/10/07 09:36:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestDrainGivesUpWhenServerDown804517098/002/d2423--- PASS: TestQueueRemove (0.02s)24242026/10/07 09:36:59 INFO Uploading batch count=124252026/10/07 09:36:59 ERROR Upload failed error="upload failed" count=12426--- PASS: TestQueueRetryMovesToBack (0.02s)24272026/10/07 09:36:59 INFO Uploading batch count=224282026/10/07 09:36:59 ERROR Upload failed error="upload failed" count=224292026/10/07 09:36:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestDrainGivesUpWhenServerDown804517098/002/e24302026/10/07 09:36:59 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestDrainGivesUpWhenServerDown804517098/002/f24312026/10/07 09:36:59 INFO Uploading batch count=124322026/10/07 09:36:59 ERROR Upload failed error="upload failed" count=124332026/10/07 09:36:59 ERROR Drain finished with paths left in queue remaining=1024342026/10/07 09:36:59 INFO Uploading batch count=124352026/10/07 09:36:59 ERROR Upload failed error="upload failed" count=124362026/10/07 09:36:59 ERROR Drain finished with paths left in queue remaining=12437--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2438--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2439--- PASS: TestDrainIsolatesPoisonPath (0.02s)2440--- PASS: TestWorkerPrunesClosureDeps (0.03s)2441--- PASS: TestWorkerSkipsGCdPaths (0.03s)2442--- PASS: TestWorkerUploadsAndRemoves (0.03s)2443--- PASS: TestQueueRemoveLargeClosure (0.05s)2444--- PASS: TestQueueConcurrentWriters (0.16s)24452026/10/07 09:36:59 ERROR Upload failed error="context deadline exceeded" count=224462026/10/07 09:36:59 ERROR Drain finished with paths left in queue remaining=42447--- PASS: TestDrainTimeout (0.21s)24482026/10/07 09:37:00 INFO Uploading batch count=124492026/10/07 09:37:00 INFO Uploading batch count=124502026/10/07 09:37:00 INFO Uploading batch count=124512026/10/07 09:37:00 ERROR Upload failed error="upload failed" count=124522026/10/07 09:37:00 INFO Uploading batch count=124532026/10/07 09:37:00 ERROR Upload failed error="upload failed" count=124542026/10/07 09:37:00 INFO Uploading batch count=124552026/10/07 09:37:00 ERROR Upload failed error="upload failed" count=124562026/10/07 09:37:00 INFO Uploading batch count=124572026/10/07 09:37:00 ERROR Upload failed error="upload failed" count=124582026/10/07 09:37:00 ERROR Drain finished with paths left in queue remaining=12459--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2460PASS2461Running signing tests...2462=== RUN TestExternalSigner2463=== PAUSE TestExternalSigner2464=== RUN TestExternalSignerWrongPublicKey2465=== PAUSE TestExternalSignerWrongPublicKey2466=== RUN TestExternalSignerErrors2467=== PAUSE TestExternalSignerErrors2468=== RUN TestExternalSignerRestartsAfterCrash2469=== PAUSE TestExternalSignerRestartsAfterCrash2470=== RUN TestExternalSignerProgramErrorKeepsProcess2471=== PAUSE TestExternalSignerProgramErrorKeepsProcess2472=== RUN TestExternalSignerClose2473=== PAUSE TestExternalSignerClose2474=== RUN TestExternalSignerRejectsInvalidPublicKey2475=== PAUSE TestExternalSignerRejectsInvalidPublicKey2476=== RUN TestExternalSignerCancellation2477=== PAUSE TestExternalSignerCancellation2478=== RUN TestGenerateFingerprint2479=== PAUSE TestGenerateFingerprint2480=== RUN TestParseSigningKey2481=== PAUSE TestParseSigningKey2482=== RUN TestSign2483=== PAUSE TestSign2484=== RUN TestSignBatch2485=== PAUSE TestSignBatch2486=== RUN TestNilKeyPublicKey2487=== PAUSE TestNilKeyPublicKey2488=== RUN TestSignErrors2489=== PAUSE TestSignErrors2490=== CONT TestExternalSigner2491=== CONT TestExternalSignerCancellation2492=== CONT TestParseSigningKey2493=== RUN TestParseSigningKey/valid_32-byte_key2494=== CONT TestSignBatch2495=== CONT TestGenerateFingerprint2496=== PAUSE TestParseSigningKey/valid_32-byte_key2497=== CONT TestExternalSignerRejectsInvalidPublicKey2498=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2499=== RUN TestExternalSignerRejectsInvalidPublicKey/#002500=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2501=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002502=== CONT TestExternalSignerErrors2503=== CONT TestExternalSignerClose2504=== CONT TestNilKeyPublicKey2505--- PASS: TestNilKeyPublicKey (0.00s)2506=== CONT TestSign2507=== CONT TestExternalSignerWrongPublicKey2508=== CONT TestExternalSignerProgramErrorKeepsProcess2509=== RUN TestGenerateFingerprint/basic_with_references2510=== PAUSE TestGenerateFingerprint/basic_with_references2511=== RUN TestGenerateFingerprint/no_references2512=== PAUSE TestGenerateFingerprint/no_references2513=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2514=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2515=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2516=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2517=== RUN TestGenerateFingerprint/invalid_nar_hash_length2518=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2519=== RUN TestGenerateFingerprint/invalid_store_path_prefix2520=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2521=== RUN TestGenerateFingerprint/invalid_reference_prefix2522=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2523=== CONT TestGenerateFingerprint/basic_with_references2524=== CONT TestGenerateFingerprint/invalid_reference_prefix2525=== RUN TestParseSigningKey/no_colon2526=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2527=== PAUSE TestParseSigningKey/no_colon2528=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2529=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2530=== CONT TestExternalSignerRestartsAfterCrash2531=== RUN TestExternalSignerErrors/wrong_shape2532=== CONT TestSignErrors2533=== PAUSE TestExternalSignerErrors/wrong_shape2534=== CONT TestGenerateFingerprint/invalid_store_path_prefix2535=== CONT TestGenerateFingerprint/invalid_nar_hash_length2536=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2537=== CONT TestGenerateFingerprint/no_references2538=== RUN TestParseSigningKey/empty_name2539=== PAUSE TestParseSigningKey/empty_name2540--- PASS: TestGenerateFingerprint (0.00s)2541 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2542 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2543 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2544 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2545 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2546 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2547 --- PASS: TestGenerateFingerprint/no_references (0.00s)2548=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2549=== RUN TestParseSigningKey/invalid_base642550=== RUN TestExternalSignerErrors/unrequested_key2551=== PAUSE TestExternalSignerErrors/unrequested_key2552=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2553=== PAUSE TestParseSigningKey/invalid_base642554=== RUN TestExternalSignerErrors/wrong_signature_name2555=== PAUSE TestExternalSignerErrors/wrong_signature_name2556=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2557=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2558=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2559=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2560=== CONT TestExternalSignerRejectsInvalidPublicKey/#002561=== RUN TestExternalSignerErrors/invalid_JSON2562=== RUN TestParseSigningKey/wrong_length2563=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2564=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2565=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2566=== PAUSE TestParseSigningKey/wrong_length2567=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2568=== CONT TestParseSigningKey/valid_32-byte_key2569=== CONT TestParseSigningKey/empty_name2570=== CONT TestParseSigningKey/wrong_length2571=== CONT TestParseSigningKey/invalid_base642572=== CONT TestParseSigningKey/no_colon2573--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2574 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2575 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2576 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2577 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2578 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2579=== PAUSE TestExternalSignerErrors/invalid_JSON2580=== RUN TestExternalSignerErrors/missing_signatures2581=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2582=== PAUSE TestExternalSignerErrors/missing_signatures2583=== RUN TestExternalSignerErrors/program_error2584=== PAUSE TestExternalSignerErrors/program_error2585=== RUN TestExternalSignerErrors/exit_at_startup2586=== PAUSE TestExternalSignerErrors/exit_at_startup2587=== RUN TestExternalSignerErrors/exit_on_request2588=== PAUSE TestExternalSignerErrors/exit_on_request2589=== RUN TestExternalSignerErrors/wrong_signatures_shape2590=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2591=== RUN TestExternalSignerErrors/too_few_signatures2592=== PAUSE TestExternalSignerErrors/too_few_signatures2593--- PASS: TestParseSigningKey (0.00s)2594 --- PASS: TestParseSigningKey/empty_name (0.00s)2595 --- PASS: TestParseSigningKey/wrong_length (0.00s)2596 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2597 --- PASS: TestParseSigningKey/no_colon (0.00s)2598 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2599 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2600=== RUN TestExternalSignerErrors/missing_signature_name2601=== PAUSE TestExternalSignerErrors/missing_signature_name2602--- PASS: TestSign (0.00s)2603=== RUN TestSignErrors/nil_key2604=== PAUSE TestSignErrors/nil_key2605=== RUN TestExternalSignerErrors/invalid_signature_base642606=== RUN TestSignErrors/nil_narinfo2607=== PAUSE TestExternalSignerErrors/invalid_signature_base642608=== PAUSE TestSignErrors/nil_narinfo2609=== RUN TestExternalSignerErrors/null2610=== RUN TestSignErrors/invalid_narinfo2611=== PAUSE TestExternalSignerErrors/null2612=== PAUSE TestSignErrors/invalid_narinfo2613=== RUN TestExternalSignerErrors/wrong_id2614=== PAUSE TestExternalSignerErrors/wrong_id2615=== RUN TestExternalSignerErrors/null_signatures2616--- PASS: TestSignBatch (0.01s)2617=== PAUSE TestExternalSignerErrors/null_signatures2618=== RUN TestExternalSignerErrors/wrong_signature_length2619=== PAUSE TestExternalSignerErrors/wrong_signature_length2620=== CONT TestExternalSignerErrors/too_few_signatures2621=== CONT TestExternalSignerErrors/exit_on_request2622=== CONT TestExternalSignerErrors/missing_signatures2623=== CONT TestExternalSignerErrors/wrong_signature_name2624=== CONT TestExternalSignerErrors/invalid_JSON2625=== CONT TestExternalSignerErrors/unrequested_key2626=== CONT TestExternalSignerErrors/wrong_shape2627=== CONT TestExternalSignerErrors/program_error2628=== CONT TestExternalSignerErrors/exit_at_startup2629=== CONT TestExternalSignerErrors/wrong_id2630=== CONT TestExternalSignerErrors/invalid_signature_base642631=== CONT TestExternalSignerErrors/missing_signature_name2632=== RUN TestSignErrors/canceled2633=== PAUSE TestSignErrors/canceled2634=== CONT TestSignErrors/nil_key2635=== CONT TestExternalSignerErrors/wrong_signature_length2636=== CONT TestExternalSignerErrors/null_signatures2637=== CONT TestExternalSignerErrors/wrong_signatures_shape2638=== CONT TestSignErrors/canceled2639=== CONT TestExternalSignerErrors/null2640=== CONT TestSignErrors/invalid_narinfo2641=== CONT TestSignErrors/nil_narinfo2642--- PASS: TestSignErrors (0.00s)2643 --- PASS: TestSignErrors/nil_key (0.00s)2644 --- PASS: TestSignErrors/canceled (0.00s)2645 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2646 --- PASS: TestSignErrors/nil_narinfo (0.00s)2647--- PASS: TestExternalSignerCancellation (0.24s)2648--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.40s)2649--- PASS: TestExternalSigner (0.61s)2650--- PASS: TestExternalSignerClose (0.78s)2651--- PASS: TestExternalSignerWrongPublicKey (0.96s)2652--- PASS: TestExternalSignerRestartsAfterCrash (1.17s)2653/private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestExternalSignerRestartsAfterCrash158051677/001/sign program: line 7: /private/var/tb/3/scratch/57f3bbd2d234d1c0/build/TestExternalSignerRestartsAfterCrash158051677/001/sign program.starts: No such file or directory2654--- PASS: TestExternalSignerErrors (0.00s)2655 --- PASS: TestExternalSignerErrors/null_signatures (1.34s)2656 --- PASS: TestExternalSignerErrors/exit_on_request (1.53s)2657 --- PASS: TestExternalSignerErrors/null (1.71s)2658 --- PASS: TestExternalSignerErrors/missing_signature_name (1.90s)2659 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (2.09s)2660 --- PASS: TestExternalSignerErrors/unrequested_key (2.27s)2661 --- PASS: TestExternalSignerErrors/invalid_JSON (2.46s)2662 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (2.74s)2663 --- PASS: TestExternalSignerErrors/exit_at_startup (2.89s)2664 --- PASS: TestExternalSignerErrors/wrong_id (3.08s)2665 --- PASS: TestExternalSignerErrors/missing_signatures (3.27s)2666 --- PASS: TestExternalSignerErrors/wrong_signature_name (3.45s)2667 --- PASS: TestExternalSignerErrors/wrong_signature_length (3.64s)2668 --- PASS: TestExternalSignerErrors/too_few_signatures (3.82s)2669 --- PASS: TestExternalSignerErrors/program_error (4.01s)2670 --- PASS: TestExternalSignerErrors/wrong_shape (4.20s)2671PASS2672Running OpenBao signer tests...2673=== RUN TestSign2674=== PAUSE TestSign2675=== RUN TestSignErrors2676=== PAUSE TestSignErrors2677=== RUN TestServe2678=== PAUSE TestServe2679=== RUN TestServeRejectsGarbage2680=== PAUSE TestServeRejectsGarbage2681=== CONT TestSign2682=== CONT TestServeRejectsGarbage2683=== CONT TestSignErrors2684=== RUN TestSignErrors/http_error2685--- PASS: TestServeRejectsGarbage (0.00s)2686=== CONT TestServe2687=== PAUSE TestSignErrors/http_error2688=== RUN TestSignErrors/invalid_json2689=== PAUSE TestSignErrors/invalid_json2690=== RUN TestSignErrors/no_prefix2691=== PAUSE TestSignErrors/no_prefix2692=== RUN TestSignErrors/invalid_base642693=== PAUSE TestSignErrors/invalid_base642694=== CONT TestSignErrors/http_error2695=== CONT TestSignErrors/no_prefix2696=== CONT TestSignErrors/invalid_base642697=== CONT TestSignErrors/invalid_json2698--- PASS: TestServe (0.00s)2699--- PASS: TestSign (0.00s)2700--- PASS: TestSignErrors (0.00s)2701 --- PASS: TestSignErrors/invalid_base64 (0.00s)2702 --- PASS: TestSignErrors/invalid_json (0.00s)2703 --- PASS: TestSignErrors/http_error (0.00s)2704 --- PASS: TestSignErrors/no_prefix (0.00s)2705PASS