niks3-go-unit-tests log

succeeded `niks3-go-unit-tests` `checks.x86_64-linux.go-unit-tests` · build #403 · raw

1tribuchet: building on jamie2Running 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.05s)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 TestRetryTimeoutOutlastsMaxRetries56=== PAUSE TestRetryTimeoutOutlastsMaxRetries57=== RUN TestShellSplit58=== PAUSE TestShellSplit59=== RUN TestShellSplitErrors60=== PAUSE TestShellSplitErrors61=== RUN TestStreamPushReportsEveryPath62=== PAUSE TestStreamPushReportsEveryPath63=== RUN TestStreamPushBatchesUnderLoad64=== PAUSE TestStreamPushBatchesUnderLoad65=== RUN TestStreamPushIsolatesFailures66=== PAUSE TestStreamPushIsolatesFailures67=== RUN TestStreamPushGivesUpOnDeadServer68=== PAUSE TestStreamPushGivesUpOnDeadServer69=== RUN TestStreamPushRequestLine70=== PAUSE TestStreamPushRequestLine71=== RUN TestStreamPushReportsSignatures72=== PAUSE TestStreamPushReportsSignatures73=== RUN TestStreamPushReportsSkippedPaths74=== PAUSE TestStreamPushReportsSkippedPaths75=== RUN TestClientSignaturesByStorePath76=== PAUSE TestClientSignaturesByStorePath77=== RUN TestStreamPushStopsWhenCanceled78=== PAUSE TestStreamPushStopsWhenCanceled79=== RUN TestSetClientTLS80=== PAUSE TestSetClientTLS81=== RUN TestSetClientTLSDoesNotMutateDefaultTransport82=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport83=== RUN TestSetClientTLSErrors84=== PAUSE TestSetClientTLSErrors85=== RUN TestStaticToken86=== PAUSE TestStaticToken87=== RUN TestFileTokenReadsAndCaches88=== PAUSE TestFileTokenReadsAndCaches89=== RUN TestFileTokenMissing90=== PAUSE TestFileTokenMissing91=== RUN TestFileTokenEmpty92=== PAUSE TestFileTokenEmpty93=== RUN TestScriptTokenNoExpiryRerunsEveryCall94=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall95=== RUN TestScriptTokenCachesUntilRefresh96=== PAUSE TestScriptTokenCachesUntilRefresh97=== RUN TestScriptTokenEmptyToken98=== PAUSE TestScriptTokenEmptyToken99=== RUN TestScriptTokenBadJSON100=== PAUSE TestScriptTokenBadJSON101=== RUN TestScriptTokenScriptFails102=== PAUSE TestScriptTokenScriptFails103=== RUN TestScriptTokenEmptyCommand104=== PAUSE TestScriptTokenEmptyCommand105=== CONT TestDoServerRequestAttachesToken106=== CONT TestStaticToken107--- PASS: TestStaticToken (0.00s)108=== CONT TestRateLimiterFeedback109=== CONT TestSetClientTLSErrors110=== CONT TestSetClientTLSDoesNotMutateDefaultTransport111=== CONT TestSetClientTLS112=== CONT TestStreamPushStopsWhenCanceled113--- PASS: TestStreamPushStopsWhenCanceled (0.00s)114=== CONT TestDumpPathSingleFile115=== CONT TestClientSignaturesByStorePath116--- PASS: TestClientSignaturesByStorePath (0.00s)117=== CONT TestScriptTokenEmptyToken118=== CONT TestStreamPushReportsSkippedPaths119=== CONT TestStreamPushReportsSignatures120=== CONT TestStreamPushRequestLine121=== CONT TestStreamPushGivesUpOnDeadServer122=== CONT TestStreamPushIsolatesFailures123=== CONT TestScriptTokenCachesUntilRefresh124=== CONT TestStreamPushBatchesUnderLoad125=== CONT TestStreamPushReportsEveryPath126=== CONT TestShellSplitErrors127=== CONT TestConvertHashToNix32128=== CONT TestScriptTokenEmptyCommand129=== CONT TestEncodeNixBase32130=== RUN TestEncodeNixBase32/test_string_hash1312026/10/09 17:37:42 ERROR Upload failed error="connection refused" count=20132=== CONT TestShellSplit1332026/10/09 17:37:42 ERROR Upload failed error="bad path" count=3134=== CONT TestParsePathInfoJSON135=== RUN TestParsePathInfoJSON/Nix_format1362026/10/09 17:37:42 ERROR Server seems unavailable, giving up on batch untried=17137=== CONT TestParsePathInfoJSONMultiplePaths138=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths1392026/10/09 17:37:42 ERROR Upload failed error=boom count=1140=== CONT TestScriptTokenScriptFails141=== CONT TestDoWithRetry_BodyReplayedViaGetBody142=== CONT TestResolveStorePath143=== CONT TestScriptTokenBadJSON144=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess145=== RUN TestRateLimiterFeedback/429_enables_limiter146--- PASS: TestStreamPushReportsSkippedPaths (0.00s)147--- PASS: TestShellSplitErrors (0.00s)148=== CONT TestPathInfoCACompatibility1492026/10/09 17:37:42 ERROR Upload failed error=boom count=1150=== RUN TestConvertHashToNix32/SRI_format_to_Nix32151=== CONT TestEncodeNixBase32WithRealHash1522026/10/09 17:37:42 WARN Rate limiter enabled after throttle name=server-test rate=5153=== PAUSE TestEncodeNixBase32/test_string_hash154=== RUN TestEncodeNixBase32/empty_input155=== CONT TestDumpPathWriterError156=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths157=== CONT TestRetryTimeoutOutlastsMaxRetries158=== PAUSE TestParsePathInfoJSON/Nix_format159--- PASS: TestStreamPushReportsEveryPath (0.00s)160=== CONT TestPathInfoHashCompatibility161=== RUN TestSetClientTLSErrors/missing_cert_file162=== CONT TestDumpPathMatchesNix163=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)164=== PAUSE TestRateLimiterFeedback/429_enables_limiter165=== RUN TestPathInfoCACompatibility/null_ca_field166=== PAUSE TestPathInfoCACompatibility/null_ca_field167=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32168=== RUN TestConvertHashToNix32/already_Nix32_format169=== PAUSE TestConvertHashToNix32/already_Nix32_format170=== PAUSE TestEncodeNixBase32/empty_input171=== CONT TestGetStorePathHash172=== RUN TestGetStorePathHash/valid_store_path173=== PAUSE TestGetStorePathHash/valid_store_path174=== CONT TestFilterOversizedClosures1752026/10/09 17:37:42 WARN Rate limiter enabled after throttle name=server-test rate=5176=== CONT TestPartSizeForNAR177=== RUN TestPartSizeForNAR/zero_stays_at_minimum178=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths179=== RUN TestParsePathInfoJSON/Lix_format1802026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:35251181--- PASS: TestScriptTokenEmptyCommand (0.00s)1822026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:34175183=== PAUSE TestSetClientTLSErrors/missing_cert_file184=== CONT TestUploadMultipart_SupersededByPeer185=== CONT TestUploadMultipart_PartsInParallel186=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)187=== RUN TestSetClientTLS/rejects_connection_without_client_cert188=== RUN TestRateLimiterFeedback/503_enables_limiter189=== RUN TestPathInfoCACompatibility/old_string_format_-_text190=== RUN TestConvertHashToNix32/invalid_format191=== RUN TestGetStorePathHash/basename_without_hyphen_should_error192=== RUN TestFilterOversizedClosures/no_limit_keeps_everything193=== CONT TestFileTokenEmpty194--- PASS: TestScriptTokenEmptyToken (0.00s)195=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum196=== RUN TestPartSizeForNAR/small_stays_at_minimum197=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything198=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths199=== CONT TestScriptTokenNoExpiryRerunsEveryCall2002026/10/09 17:37:42 WARN Rate limiter backed off name=server-test rate=5201=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2022026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:35251203=== PAUSE TestParsePathInfoJSON/Lix_format204=== RUN TestSetClientTLSErrors/missing_key_file205=== RUN TestUploadMultipart_SupersededByPeer/exists206=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon207=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert208=== PAUSE TestRateLimiterFeedback/503_enables_limiter209=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text210=== PAUSE TestConvertHashToNix32/invalid_format211=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error212=== PAUSE TestPartSizeForNAR/small_stays_at_minimum213--- PASS: TestShellSplit (0.00s)214=== CONT TestFileTokenMissing215--- PASS: TestStreamPushIsolatesFailures (0.00s)216--- PASS: TestEncodeNixBase32WithRealHash (0.00s)217--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)218--- PASS: TestStreamPushReportsSignatures (0.00s)219--- PASS: TestScriptTokenScriptFails (0.00s)220--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)221--- PASS: TestScriptTokenBadJSON (0.00s)222=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun223--- PASS: TestResolveStorePath (0.00s)224--- PASS: TestDoServerRequestAttachesToken (0.01s)225--- PASS: TestFileTokenEmpty (0.00s)226--- PASS: TestFileTokenMissing (0.00s)227=== CONT TestFileTokenReadsAndCaches228=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica229=== PAUSE TestUploadMultipart_SupersededByPeer/exists230=== RUN TestUploadMultipart_SupersededByPeer/missing231=== PAUSE TestUploadMultipart_SupersededByPeer/missing232=== CONT TestCaseHackSuffix233=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter234=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2352026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:34175236=== RUN TestFilterOversizedClosures/all_closures_skipped237=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2382026/10/09 17:37:42 INFO Garbage collection started239=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive240=== RUN TestPathInfoCACompatibility/new_structured_format_-_text241=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text242=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method243=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method244=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon245=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI2462026/10/09 17:37:42 INFO Garbage collection started247=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI248=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512249=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512250=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error251=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error252=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error253=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error254=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths255=== CONT TestConvertHashToNix32/invalid_format256=== CONT TestConvertHashToNix32/already_Nix32_format257=== CONT TestEncodeNixBase32/empty_input258=== CONT TestUploadMultipart_SupersededByPeer/missing259=== RUN TestParsePathInfoJSON/empty_input260=== PAUSE TestParsePathInfoJSON/empty_input261=== PAUSE TestSetClientTLSErrors/missing_key_file262--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)263=== CONT TestRegisterUploadedObjectReusesConnections264=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA265=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter266=== CONT TestEncodeNixBase32/test_string_hash267=== PAUSE TestFilterOversizedClosures/all_closures_skipped268=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths269=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method270=== RUN TestSetClientTLSErrors/missing_ca_file271=== CONT TestPathInfoCACompatibility/old_string_format_-_text272=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter273=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum274=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum275=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts276=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive277=== CONT TestConvertHashToNix32/SRI_format_to_Nix32278=== RUN TestParsePathInfoJSON/whitespace_only279--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)2802026/10/09 17:37:42 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=02812026/10/09 17:37:42 WARN Garbage collection finished on another replica. Its statistics are not available here2822026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:34175283=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA284=== CONT TestPathInfoCACompatibility/null_ca_field285=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error286=== CONT TestGetStorePathHash/basename_without_hyphen_should_error287=== CONT TestFilterOversizedClosures/no_limit_keeps_everything288=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped289=== CONT TestFilterOversizedClosures/all_closures_skipped2902026/10/09 17:37:42 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=20002912026/10/09 17:37:42 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=50292=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts293=== RUN TestPartSizeForNAR/1_TiB294=== PAUSE TestPartSizeForNAR/1_TiB295=== CONT TestUploadMultipart_SupersededByPeer/exists296--- PASS: TestDumpPathSingleFile (0.04s)297--- PASS: TestEncodeNixBase32 (0.01s)298 --- PASS: TestEncodeNixBase32/empty_input (0.00s)299 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)300=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)301--- PASS: TestFileTokenReadsAndCaches (0.00s)302--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)303 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)304 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)305=== PAUSE TestSetClientTLSErrors/missing_ca_file306=== RUN TestSetClientTLSErrors/invalid_ca_file307=== PAUSE TestSetClientTLSErrors/invalid_ca_file308=== CONT TestSetClientTLSErrors/missing_cert_file309=== CONT TestSetClientTLSErrors/invalid_ca_file310=== CONT TestGetStorePathHash/valid_store_path311=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512312--- PASS: TestConvertHashToNix32 (0.01s)313 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)314 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)315 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)316--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.03s)317=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter318=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI319=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon3202026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:34175321=== CONT TestSetClientTLSErrors/missing_ca_file322=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error323=== PAUSE TestParsePathInfoJSON/whitespace_only324=== RUN TestSetClientTLS/preserves_debug_logging_transport325=== CONT TestPathInfoCACompatibility/new_structured_format_-_text326=== RUN TestPartSizeForNAR/5_TiB_S3_max_object327=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object328=== CONT TestSetClientTLSErrors/missing_key_file329--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)330=== CONT TestRateLimiterFeedback/429_enables_limiter331=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter332=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter333=== CONT TestRateLimiterFeedback/503_enables_limiter3342026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:34175335=== RUN TestParsePathInfoJSON/invalid_JSON336=== PAUSE TestParsePathInfoJSON/invalid_JSON337=== CONT TestParsePathInfoJSON/Nix_format338=== PAUSE TestSetClientTLS/preserves_debug_logging_transport3392026/10/09 17:37:42 WARN Rate limiter enabled after throttle name=server-test rate=5340=== CONT TestSetClientTLS/rejects_connection_without_client_cert3412026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:42453342=== CONT TestParsePathInfoJSON/Lix_format3432026/10/09 17:37:42 WARN Rate limiter enabled after throttle name=server-test rate=5344=== CONT TestParsePathInfoJSON/whitespace_only3452026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:43167346--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.03s)3472026/10/09 17:37:42 WARN Rate limiter backed off name=server-test rate=5348=== CONT TestParsePathInfoJSON/invalid_JSON3492026/10/09 17:37:42 WARN Rate limiter backed off name=server-test rate=5350=== CONT TestSetClientTLS/preserves_debug_logging_transport3512026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:34175352=== RUN TestPartSizeForNAR/capped_at_5_GiB353=== PAUSE TestPartSizeForNAR/capped_at_5_GiB354=== CONT TestPartSizeForNAR/zero_stays_at_minimum355=== CONT TestPartSizeForNAR/1_TiB356=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts357=== CONT TestParsePathInfoJSON/empty_input358--- PASS: TestFilterOversizedClosures (0.03s)359 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)360 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)361 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)362--- PASS: TestUploadMultipart_SupersededByPeer (0.02s)363 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.01s)364 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)365=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum3662026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:34175367=== CONT TestPartSizeForNAR/small_stays_at_minimum368=== CONT TestPartSizeForNAR/capped_at_5_GiB369=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA370=== CONT TestPartSizeForNAR/5_TiB_S3_max_object371--- PASS: TestPathInfoCACompatibility (0.03s)372 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.01s)373 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.01s)374 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)375 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)376 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)377--- PASS: TestPathInfoHashCompatibility (0.03s)378 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)379 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)380 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)381 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)382--- PASS: TestGetStorePathHash (0.03s)383 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)384 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)385 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)386 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)387--- PASS: TestRateLimiterFeedback (0.05s)388 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)389 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)390 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)391 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)392--- PASS: TestSetClientTLSErrors (0.05s)393 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)394 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)395 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)396 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)3972026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:34175398--- PASS: TestParsePathInfoJSON (0.04s)399 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)400 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)401 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)402 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)403 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)404--- PASS: TestPartSizeForNAR (0.04s)405 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)406 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)407 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)408 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)409 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)410 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)411 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)4122026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:341754132026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:341754142026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:341754152026/10/09 17:37:42 http: TLS handshake error from 127.0.0.1:43736: remote error: tls: bad certificate416--- PASS: TestStreamPushRequestLine (0.05s)4172026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:34175418--- PASS: TestSetClientTLS (0.05s)419 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)420 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)421 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)4222026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:341754232026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:341754242026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:341754252026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:341754262026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:341754272026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:34175428--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)4292026/10/09 17:37:42 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:34175430--- PASS: TestCaseHackSuffix (0.03s)431--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.06s)432--- PASS: TestDumpPathWriterError (0.06s)433--- PASS: TestStreamPushBatchesUnderLoad (0.10s)434--- PASS: TestDumpPathMatchesNix (0.11s)435--- PASS: TestUploadMultipart_PartsInParallel (0.64s)436--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)437PASS438Running server tests...439The files belonging to this database system will be owned by user "nixbld".440This user must also own the server process.441442The database cluster will be initialized with locale "C".443The default database encoding has accordingly been set to "SQL_ASCII".444The default text search configuration will be set to "english".445446Data page checksums are enabled.447448creating directory /build/postgres4068946920/data ... ok449creating subdirectories ... ok450selecting dynamic shared memory implementation ... posix451selecting default "max_connections" ... 100452selecting default "shared_buffers" ... 128MB453selecting default time zone ... UTC454creating configuration files ... ok455running bootstrap script ... ok456performing post-bootstrap initialization ... ok457syncing data to disk ... ok458459initdb: warning: enabling "trust" authentication for local connections460initdb: 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.461462Success. You can now start the database server using:463464 pg_ctl -D /build/postgres4068946920/data -l logfile start465466/build/postgres4068946920:5432 - no response4672026-10-09 17:37:44.486 UTC [128] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4682026-10-09 17:37:44.487 UTC [128] LOG: listening on Unix socket "/build/postgres4068946920/.s.PGSQL.5432"4692026-10-09 17:37:44.492 UTC [135] LOG: database system was shut down at 2026-10-09 17:37:44 UTC4702026-10-09 17:37:44.495 UTC [128] LOG: database system is ready to accept connections471/build/postgres4068946920:5432 - accepting connections472{"timestamp":"2026-10-09T17:37:44.805663061Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"e7c990d8-ba94-4a74-b2d6-19e624deea2d","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(392)"}473=== RUN TestFarmLeadRoutes474=== PAUSE TestFarmLeadRoutes475=== RUN TestService_AuthMiddleware476=== PAUSE TestService_AuthMiddleware477=== RUN TestService_AuthMiddleware_MTLSProxyHeader478=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader479=== RUN TestService_AuthMiddleware_MTLSBoundSubjects480=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects481=== RUN TestService_ReadAuthMiddleware482=== PAUSE TestService_ReadAuthMiddleware483=== RUN TestService_AuthMiddleware_OIDC484=== PAUSE TestService_AuthMiddleware_OIDC485=== RUN TestService_RequireScope_OIDC486=== PAUSE TestService_RequireScope_OIDC487=== RUN TestService_ReadScope_PublicByDefault488=== PAUSE TestService_ReadScope_PublicByDefault489=== RUN TestCacheConfigHandler490=== PAUSE TestCacheConfigHandler491=== RUN TestCacheStatsHandler492=== PAUSE TestCacheStatsHandler493=== RUN TestClientCADerivations494=== PAUSE TestClientCADerivations495=== RUN TestClientErrorHandling496=== PAUSE TestClientErrorHandling497=== RUN TestClientIntegration498=== PAUSE TestClientIntegration499=== RUN TestClientMultipleUploads500=== PAUSE TestClientMultipleUploads501=== RUN TestClientWithDependencies502=== PAUSE TestClientWithDependencies503=== RUN TestClientSharedPathCommittedMidPush504=== PAUSE TestClientSharedPathCommittedMidPush505=== RUN TestPinProtectsFromGC506=== PAUSE TestPinProtectsFromGC507=== RUN TestClientPushesUseOnePush508=== PAUSE TestClientPushesUseOnePush509=== RUN TestClientFallsBackToClosures510=== PAUSE TestClientFallsBackToClosures511=== RUN TestDeleteClosuresRacingPins512=== PAUSE TestDeleteClosuresRacingPins513=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock514=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock515=== RUN TestResolveDBConnectionString516=== PAUSE TestResolveDBConnectionString517=== RUN TestConnectWaitsForAPeerMigration518=== PAUSE TestConnectWaitsForAPeerMigration519=== RUN TestLeadElectsOneAndHandsOver520=== PAUSE TestLeadElectsOneAndHandsOver521=== RUN TestLeadScopedToFarm522=== PAUSE TestLeadScopedToFarm523=== RUN TestLeadIncumbentWinsAfterRestart5242026/10/09 17:37:45 INFO lead: acquired remote=192.0.2.1:12345252026/10/09 17:37:45 INFO lead: released remote=192.0.2.1:12345262026/10/09 17:37:45 INFO lead: acquired remote=192.0.2.1:12345272026/10/09 17:37:46 INFO lead: released remote=192.0.2.1:1234528--- PASS: TestLeadIncumbentWinsAfterRestart (1.91s)529=== RUN TestLeadIncumbentAnnouncesAtOnce530=== PAUSE TestLeadIncumbentAnnouncesAtOnce531=== RUN TestLeadEndsOnShutdown532=== PAUSE TestLeadEndsOnShutdown533=== RUN TestLeadEndsWhenItsConnectionHangs5342026/10/09 17:37:46 INFO lead: acquired remote=192.0.2.1:12345352026-10-09 17:37:48.335 UTC [575] FATAL: terminating connection due to administrator command5362026/10/09 17:37:48 INFO lead: acquired remote=192.0.2.1:12345372026/10/09 17:37:49 WARN lead: lock connection lost error="timeout: context deadline exceeded"5382026/10/09 17:37:49 INFO lead: released remote=192.0.2.1:12345392026/10/09 17:37:49 INFO lead: released remote=192.0.2.1:1234540--- PASS: TestLeadEndsWhenItsConnectionHangs (2.91s)541=== RUN TestGCAdvisoryLockBlocksConcurrentRun542=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun543=== RUN TestGCBugBareHashReferences544=== PAUSE TestGCBugBareHashReferences545=== RUN TestGCMetrics546=== PAUSE TestGCMetrics547=== RUN TestPushDedupSurvivesConcurrentGC548=== PAUSE TestPushDedupSurvivesConcurrentGC549=== RUN TestDeduplicatedObjectsRecordedAsPending550=== PAUSE TestDeduplicatedObjectsRecordedAsPending551=== RUN TestGCSweepSkipsPendingObjects552=== PAUSE TestGCSweepSkipsPendingObjects553=== RUN TestTombstonedObjectOfferedWithoutWaiting554=== PAUSE TestTombstonedObjectOfferedWithoutWaiting555=== RUN TestGCSweepDeliversEachKeyOnce556=== PAUSE TestGCSweepDeliversEachKeyOnce557=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection558=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection559=== RUN TestForceGCDuringPushOffersSweptObject560=== PAUSE TestForceGCDuringPushOffersSweptObject561=== RUN TestFailedS3DeleteKeepsTombstone562=== PAUSE TestFailedS3DeleteKeepsTombstone563=== RUN TestSweepSkipsRowsLockedByPush564=== PAUSE TestSweepSkipsRowsLockedByPush565=== RUN TestRegisterCompletedObjectNeedsPendingRow566=== PAUSE TestRegisterCompletedObjectNeedsPendingRow567=== RUN TestGetExistingObjectsLocksRows568=== PAUSE TestGetExistingObjectsLocksRows569=== RUN TestSweepRechecksPendingAfterLocking570=== PAUSE TestSweepRechecksPendingAfterLocking571=== RUN TestPushWaitsForSweepHoldingRow572=== PAUSE TestPushWaitsForSweepHoldingRow573=== RUN TestCommitRacingPendingCleanupKeepsObjects574=== PAUSE TestCommitRacingPendingCleanupKeepsObjects575=== RUN TestGCEndsOnShutdown576=== PAUSE TestGCEndsOnShutdown577=== RUN TestGCTaskStore_StartNew578=== PAUSE TestGCTaskStore_StartNew579=== RUN TestGCTaskStore_DeduplicateSameParams580=== PAUSE TestGCTaskStore_DeduplicateSameParams581=== RUN TestGCTaskStore_ConflictDifferentParams582=== PAUSE TestGCTaskStore_ConflictDifferentParams583=== RUN TestGCTaskStore_GetEmpty584=== PAUSE TestGCTaskStore_GetEmpty585=== RUN TestGCTaskStore_GetReturnsLatest586=== PAUSE TestGCTaskStore_GetReturnsLatest587=== RUN TestGCTaskStore_CompletedAllowsNewTask588=== PAUSE TestGCTaskStore_CompletedAllowsNewTask589=== RUN TestGCTaskStore_PhaseUpdates590=== PAUSE TestGCTaskStore_PhaseUpdates591=== RUN TestGCTaskStore_Fail592=== PAUSE TestGCTaskStore_Fail593=== RUN TestGracefulShutdownDrainsInflight594=== PAUSE TestGracefulShutdownDrainsInflight595=== RUN TestService_healthCheckHandler596=== PAUSE TestService_healthCheckHandler597=== RUN TestService_readinessHandler598=== PAUSE TestService_readinessHandler599=== RUN TestGenerateLandingPage600=== PAUSE TestGenerateLandingPage601=== RUN TestCacheConfigHandlerMaxNarSize602=== PAUSE TestCacheConfigHandlerMaxNarSize603=== RUN TestCreatePendingClosureRejectsOversizedNAR604=== PAUSE TestCreatePendingClosureRejectsOversizedNAR605=== RUN TestNARDeduplicationMetadataUploadBug606=== PAUSE TestNARDeduplicationMetadataUploadBug607=== RUN TestMetricsInventory608=== PAUSE TestMetricsInventory609=== RUN TestMetricsCommit610=== PAUSE TestMetricsCommit611=== RUN TestService_NativeMTLS612=== PAUSE TestService_NativeMTLS613=== RUN TestServerTLSConfig614=== PAUSE TestServerTLSConfig615=== RUN TestMultipartCleanup616=== PAUSE TestMultipartCleanup617=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded618=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded619=== RUN TestPendingCleanupUsesOneCutoff620=== PAUSE TestPendingCleanupUsesOneCutoff621=== RUN TestObjectStatsTrigger622=== PAUSE TestObjectStatsTrigger623=== RUN TestObjectStatsLargeCommit624=== PAUSE TestObjectStatsLargeCommit625=== RUN TestOrphanedObjectsGC626=== PAUSE TestOrphanedObjectsGC627=== RUN TestOrphanedObjectsGCStressTest628=== PAUSE TestOrphanedObjectsGCStressTest629=== RUN TestCreatePin_ReservedPins630=== PAUSE TestCreatePin_ReservedPins631=== RUN TestPresentReportsOnlyClosureRoots632=== PAUSE TestPresentReportsOnlyClosureRoots633=== RUN TestPresentRefreshesOnlyStaleClosures634=== PAUSE TestPresentRefreshesOnlyStaleClosures635=== RUN TestPresentNotReportedWhileGCDeletesClosure636=== PAUSE TestPresentNotReportedWhileGCDeletesClosure637=== RUN TestParseSingleRange638=== PAUSE TestParseSingleRange639=== RUN TestProxyHeadersOnlyTrustedOnSocket6402026/10/09 17:37:49 INFO Starting HTTP server address=127.0.0.1:443296412026/10/09 17:37:49 INFO Starting HTTP server address=proxy.sock6422026/10/09 17:37:49 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6432026/10/09 17:37:49 INFO Shutdown signal received, draining in-flight requests timeout=10s644--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.12s)645=== RUN TestIsValidCachePath646=== PAUSE TestIsValidCachePath647=== RUN TestReadProxyNarinfo648=== PAUSE TestReadProxyNarinfo649=== RUN TestReadProxyNarinfoAlreadyDecompressed650=== PAUSE TestReadProxyNarinfoAlreadyDecompressed651=== RUN TestReadProxyContentNegotiation652=== PAUSE TestReadProxyContentNegotiation653=== RUN TestReadProxyNarStreaming654=== PAUSE TestReadProxyNarStreaming655=== RUN TestReadProxy404656=== PAUSE TestReadProxy404657=== RUN TestReadProxyInvalidPath658=== PAUSE TestReadProxyInvalidPath659=== RUN TestReadProxyHead660=== PAUSE TestReadProxyHead661=== RUN TestReadProxyOutlastsServerWriteTimeout662=== PAUSE TestReadProxyOutlastsServerWriteTimeout663=== RUN TestReadProxyConditionalGet664=== PAUSE TestReadProxyConditionalGet665=== RUN TestReadProxyRootRedirectsToIndexHTML666=== PAUSE TestReadProxyRootRedirectsToIndexHTML667=== RUN TestReadProxyDisabled668=== PAUSE TestReadProxyDisabled669=== RUN TestReadRedirectNar670=== PAUSE TestReadRedirectNar671=== RUN TestReadRedirectKeepsNarinfoProxied672=== PAUSE TestReadRedirectKeepsNarinfoProxied673=== RUN TestReadProxyRangeRequest674=== PAUSE TestReadProxyRangeRequest675=== RUN TestReadRedirectUsesPublicS3URL676=== PAUSE TestReadRedirectUsesPublicS3URL677=== RUN TestPush_OverlappingRootsStoreOneRowPerKey678=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey679=== RUN TestPush_CompleteCommitsEveryRoot680=== PAUSE TestPush_CompleteCommitsEveryRoot681=== RUN TestPush_RepeatedRootCommitsOnce682=== PAUSE TestPush_RepeatedRootCommitsOnce683=== RUN TestPush_CompleteWaitsForCleanupOfThePush684=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush685=== RUN TestPush_RootsAreLockedInByteOrder686=== PAUSE TestPush_RootsAreLockedInByteOrder687=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit688=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit689=== RUN TestPush_RejectsBadRequests690=== PAUSE TestPush_RejectsBadRequests691=== RUN TestPush_SignsNarinfosOfItsPendingObjects692=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects693=== RUN TestRedundantMultipartUpload694=== PAUSE TestRedundantMultipartUpload695=== RUN TestCompleteMultipartUpload_ErrorButObjectExists696=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists697=== RUN TestCompletedNarNotReofferedAcrossClosures698=== PAUSE TestCompletedNarNotReofferedAcrossClosures699=== RUN TestPresignedUploadRegisteredBeforeCommit700=== PAUSE TestPresignedUploadRegisteredBeforeCommit701=== RUN TestService_Rustfstest702=== PAUSE TestService_Rustfstest703=== RUN TestParseSize704=== PAUSE TestParseSize705=== RUN TestSkippedUploadsHandler706=== PAUSE TestSkippedUploadsHandler707=== RUN TestSystemdListenerNotActivated708--- PASS: TestSystemdListenerNotActivated (0.00s)709=== RUN TestWatchdogBeatsWhenHealthy710--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)711=== RUN TestWatchdogSkipsWhenUnhealthy7122026/10/09 17:37:49 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7132026/10/09 17:37:49 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7142026/10/09 17:37:49 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7152026/10/09 17:37:49 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7162026/10/09 17:37:49 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7172026/10/09 17:37:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7182026/10/09 17:37:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7192026/10/09 17:37:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7202026/10/09 17:37:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7212026/10/09 17:37:50 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"722--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)723=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle724=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle725=== RUN TestProxyWriteTimeout726=== PAUSE TestProxyWriteTimeout727=== RUN TestPendingClosureWriteTimeout728=== PAUSE TestPendingClosureWriteTimeout729=== RUN TestIsValidUploadKey730=== PAUSE TestIsValidUploadKey731=== RUN TestUploadHandlersRejectInvalidKeys732=== PAUSE TestUploadHandlersRejectInvalidKeys733=== RUN TestUploadHandlersRejectOversizedBody734=== PAUSE TestUploadHandlersRejectOversizedBody735=== RUN TestService_cleanupPendingClosuresHandler736=== PAUSE TestService_cleanupPendingClosuresHandler737=== RUN TestService_createPendingClosureHandler738=== PAUSE TestService_createPendingClosureHandler739=== RUN TestService_verifyS3Integrity740=== PAUSE TestService_verifyS3Integrity741=== RUN TestCompleteMultipartUnregistered742=== PAUSE TestCompleteMultipartUnregistered743=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT744=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT745=== CONT TestFarmLeadRoutes746=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle747=== CONT TestReadProxyNarStreaming748=== CONT TestPush_RepeatedRootCommitsOnce749=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT750=== CONT TestCompleteMultipartUnregistered751=== CONT TestService_verifyS3Integrity752=== CONT TestService_createPendingClosureHandler753=== CONT TestService_cleanupPendingClosuresHandler754=== CONT TestUploadHandlersRejectOversizedBody755=== CONT TestUploadHandlersRejectInvalidKeys756=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info757=== CONT TestIsValidUploadKey758=== CONT TestPendingClosureWriteTimeout759=== CONT TestProxyWriteTimeout760=== CONT TestSkippedUploadsHandler761=== CONT TestParseSize762=== CONT TestService_Rustfstest763=== CONT TestPresignedUploadRegisteredBeforeCommit764=== CONT TestCompletedNarNotReofferedAcrossClosures765=== CONT TestCompleteMultipartUpload_ErrorButObjectExists766=== CONT TestRedundantMultipartUpload767=== CONT TestPush_SignsNarinfosOfItsPendingObjects768=== CONT TestPush_RejectsBadRequests769=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit770=== RUN TestFarmLeadRoutes//api/farm/lead771=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info772=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal773=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal774=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key775=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key776=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key777=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key778=== RUN TestIsValidUploadKey/narinfo779=== PAUSE TestIsValidUploadKey/narinfo780=== RUN TestIsValidUploadKey/nar_zst781=== PAUSE TestFarmLeadRoutes//api/farm/lead782=== PAUSE TestIsValidUploadKey/nar_zst783=== RUN TestIsValidUploadKey/nar_xz7842026/10/09 17:37:50 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000785=== RUN TestPendingClosureWriteTimeout/empty786--- PASS: TestParseSize (0.00s)787=== CONT TestPush_RootsAreLockedInByteOrder788=== CONT TestPush_CompleteWaitsForCleanupOfThePush789=== RUN TestProxyWriteTimeout/narinfo790=== PAUSE TestProxyWriteTimeout/narinfo791=== RUN TestFarmLeadRoutes//api/farm/lead/build-x86792=== RUN TestProxyWriteTimeout/1_GiB_nar793=== PAUSE TestIsValidUploadKey/nar_xz794=== PAUSE TestPendingClosureWriteTimeout/empty795=== RUN TestPendingClosureWriteTimeout/400_objects796=== PAUSE TestFarmLeadRoutes//api/farm/lead/build-x86797=== PAUSE TestProxyWriteTimeout/1_GiB_nar798=== RUN TestIsValidUploadKey/nar_plain799=== PAUSE TestIsValidUploadKey/nar_plain800=== RUN TestIsValidUploadKey/listing801=== PAUSE TestIsValidUploadKey/listing802=== RUN TestIsValidUploadKey/build_log803=== PAUSE TestIsValidUploadKey/build_log804=== RUN TestIsValidUploadKey/build_log_home-manager_file805=== PAUSE TestIsValidUploadKey/build_log_home-manager_file806=== RUN TestIsValidUploadKey/build_log_plus_in_name807=== PAUSE TestIsValidUploadKey/build_log_plus_in_name808=== PAUSE TestPendingClosureWriteTimeout/400_objects809=== CONT TestGetExistingObjectsLocksRows810=== RUN TestPendingClosureWriteTimeout/670k_objects811=== PAUSE TestPendingClosureWriteTimeout/670k_objects812=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline813=== RUN TestProxyWriteTimeout/10_GiB_nar814=== PAUSE TestProxyWriteTimeout/10_GiB_nar815=== RUN TestIsValidUploadKey/build_log_question_mark816=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline817=== RUN TestProxyWriteTimeout/unknown_size818=== CONT TestReadProxyContentNegotiation819=== PAUSE TestProxyWriteTimeout/unknown_size820=== PAUSE TestIsValidUploadKey/build_log_question_mark821=== RUN TestIsValidUploadKey/build_log_equals822=== PAUSE TestIsValidUploadKey/build_log_equals823=== RUN TestIsValidUploadKey/realisation824=== PAUSE TestIsValidUploadKey/realisation825=== RUN TestIsValidUploadKey/realisation_plus_in_output826=== PAUSE TestIsValidUploadKey/realisation_plus_in_output827=== RUN TestIsValidUploadKey/nix-cache-info828=== PAUSE TestIsValidUploadKey/nix-cache-info829=== CONT TestReadProxyNarinfoAlreadyDecompressed830=== RUN TestIsValidUploadKey/index.html831=== PAUSE TestIsValidUploadKey/index.html832=== RUN TestIsValidUploadKey/narinfo_key,_nar_type833=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type834=== RUN TestIsValidUploadKey/nar_key,_narinfo_type835=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type836=== RUN TestIsValidUploadKey/listing_key,_narinfo_type837=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type838=== RUN TestIsValidUploadKey/traversal839=== PAUSE TestIsValidUploadKey/traversal840=== RUN TestIsValidUploadKey/traversal_nar841=== PAUSE TestIsValidUploadKey/traversal_nar842=== RUN TestIsValidUploadKey/absolute843=== PAUSE TestIsValidUploadKey/absolute844=== RUN TestIsValidUploadKey/empty_key845=== PAUSE TestIsValidUploadKey/empty_key846=== RUN TestIsValidUploadKey/unknown_type847=== PAUSE TestIsValidUploadKey/unknown_type848=== CONT TestReadProxyNarinfo849--- PASS: TestSkippedUploadsHandler (0.07s)850=== CONT TestIsValidCachePath851=== RUN TestIsValidCachePath/narinfo852=== PAUSE TestIsValidCachePath/narinfo853=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars854=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars855=== RUN TestIsValidCachePath/nar_zst856=== PAUSE TestIsValidCachePath/nar_zst857=== RUN TestIsValidCachePath/nar_xz858=== PAUSE TestIsValidCachePath/nar_xz859=== RUN TestIsValidCachePath/nar_bz2860=== PAUSE TestIsValidCachePath/nar_bz2861=== RUN TestIsValidCachePath/nar_uncompressed862=== PAUSE TestIsValidCachePath/nar_uncompressed863=== RUN TestIsValidCachePath/ls864=== PAUSE TestIsValidCachePath/ls865=== RUN TestIsValidCachePath/log866=== PAUSE TestIsValidCachePath/log867=== RUN TestIsValidCachePath/realisation868=== PAUSE TestIsValidCachePath/realisation869=== RUN TestIsValidCachePath/nix-cache-info870=== PAUSE TestIsValidCachePath/nix-cache-info871=== RUN TestIsValidCachePath/index.html872=== PAUSE TestIsValidCachePath/index.html873=== RUN TestIsValidCachePath/traversal_parent874=== PAUSE TestIsValidCachePath/traversal_parent875=== RUN TestIsValidCachePath/traversal_in_middle876=== PAUSE TestIsValidCachePath/traversal_in_middle877=== RUN TestIsValidCachePath/invalid_char_e878=== PAUSE TestIsValidCachePath/invalid_char_e879=== RUN TestIsValidCachePath/invalid_char_u880=== PAUSE TestIsValidCachePath/invalid_char_u881=== RUN TestIsValidCachePath/random_path882=== PAUSE TestIsValidCachePath/random_path883=== RUN TestIsValidCachePath/empty884=== PAUSE TestIsValidCachePath/empty885=== RUN TestIsValidCachePath/leading_slash886=== PAUSE TestIsValidCachePath/leading_slash887=== RUN TestIsValidCachePath/wrong_extension888=== PAUSE TestIsValidCachePath/wrong_extension889=== RUN TestIsValidCachePath/short_hash890=== PAUSE TestIsValidCachePath/short_hash891=== CONT TestParseSingleRange892=== RUN TestParseSingleRange/none893=== PAUSE TestParseSingleRange/none894=== RUN TestParseSingleRange/unknown_unit895=== PAUSE TestParseSingleRange/unknown_unit896=== RUN TestParseSingleRange/multi-range_ignored897=== PAUSE TestParseSingleRange/multi-range_ignored898=== RUN TestParseSingleRange/malformed_no_dash899=== PAUSE TestParseSingleRange/malformed_no_dash900=== RUN TestParseSingleRange/malformed_both_empty901=== PAUSE TestParseSingleRange/malformed_both_empty902=== RUN TestParseSingleRange/malformed_end_before_start903=== PAUSE TestParseSingleRange/malformed_end_before_start904=== RUN TestParseSingleRange/closed905=== PAUSE TestParseSingleRange/closed906=== RUN TestParseSingleRange/open-ended907=== PAUSE TestParseSingleRange/open-ended908=== RUN TestParseSingleRange/end_clamped_to_size909=== PAUSE TestParseSingleRange/end_clamped_to_size910=== RUN TestParseSingleRange/suffix911=== PAUSE TestParseSingleRange/suffix912=== RUN TestParseSingleRange/suffix_exceeds_size913=== PAUSE TestParseSingleRange/suffix_exceeds_size914=== RUN TestParseSingleRange/single_byte915=== PAUSE TestParseSingleRange/single_byte916=== RUN TestParseSingleRange/start_past_EOF917=== PAUSE TestParseSingleRange/start_past_EOF918=== RUN TestParseSingleRange/start_far_past_EOF919=== PAUSE TestParseSingleRange/start_far_past_EOF920=== CONT TestPresentNotReportedWhileGCDeletesClosure921=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale922=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale923=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh924=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh925=== CONT TestPresentRefreshesOnlyStaleClosures926=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure927=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure928=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart929=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart930=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts931=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts932=== CONT TestPresentReportsOnlyClosureRoots9332026/10/09 17:37:50 INFO Received uploads request method=POST path=/api/pending_closures9342026/10/09 17:37:50 INFO Received uploads request method=POST path=/api/pending_closures935--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.44s)936=== CONT TestCreatePin_ReservedPins9372026/10/09 17:37:50 INFO Received push request method=POST path=/api/pushes9382026/10/09 17:37:50 INFO Received uploads request method=POST path=/api/pending_closures9392026/10/09 17:37:50 INFO Received uploads request method=POST path=/api/pending_closures9402026/10/09 17:37:50 INFO Received uploads request method=POST path=/api/pending_closures9412026/10/09 17:37:50 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35831/oidc9422026/10/09 17:37:50 INFO Received complete push request method=POST path=/api/pushes/1/complete9432026/10/09 17:37:50 INFO Completed push id=1 objects=4 duration=9.103711ms944--- PASS: TestPush_RepeatedRootCommitsOnce (0.48s)945=== CONT TestOrphanedObjectsGCStressTest9462026/10/09 17:37:50 INFO Received push request method=POST path=/api/pushes9472026/10/09 17:37:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9482026/10/09 17:37:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9492026/10/09 17:37:50 INFO Signed narinfos id=1 count=19502026/10/09 17:37:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9512026/10/09 17:37:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9522026/10/09 17:37:50 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9532026/10/09 17:37:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9542026/10/09 17:37:50 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9552026/10/09 17:37:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9562026/10/09 17:37:50 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19572026/10/09 17:37:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9582026/10/09 17:37:50 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo959--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.51s)960=== CONT TestOrphanedObjectsGC961--- PASS: TestService_Rustfstest (0.51s)962=== CONT TestObjectStatsLargeCommit9632026/10/09 17:37:50 INFO Received cleanup request method=DELETE path=/api/pending_closures9642026/10/09 17:37:50 INFO Aborted multipart uploads count=0 kept=09652026/10/09 17:37:50 INFO Received uploads request method=POST path=/api/pending_closures9662026/10/09 17:37:50 INFO Received cleanup request method=DELETE path=/api/pending_closures9672026/10/09 17:37:50 INFO Aborted multipart uploads count=1 kept=0968=== RUN TestPush_RejectsBadRequests/bad_root969=== PAUSE TestPush_RejectsBadRequests/bad_root970=== RUN TestPush_RejectsBadRequests/root_not_in_objects971=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects972=== RUN TestPush_RejectsBadRequests/no_roots973=== PAUSE TestPush_RejectsBadRequests/no_roots974=== RUN TestPush_RejectsBadRequests/no_objects975=== PAUSE TestPush_RejectsBadRequests/no_objects976=== CONT TestObjectStatsTrigger9772026/10/09 17:37:50 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9782026-10-09 17:37:50.655 UTC [655] ERROR: Closure does not exist: id=19792026-10-09 17:37:50.655 UTC [655] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9802026-10-09 17:37:50.655 UTC [655] STATEMENT: -- name: CommitPendingClosure :one981 SELECT commit_pending_closure($1::bigint)::bigint982 983--- PASS: TestService_cleanupPendingClosuresHandler (0.57s)984=== CONT TestPendingCleanupUsesOneCutoff9852026/10/09 17:37:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9862026/10/09 17:37:50 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst987--- PASS: TestCompleteMultipartUnregistered (0.60s)988=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded9892026/10/09 17:37:50 INFO Received uploads request method=POST path=/api/pending_closures9902026/10/09 17:37:50 INFO Received push request method=POST path=/api/pushes9912026/10/09 17:37:50 INFO Received uploads request method=POST path=/api/pending_closures9922026/10/09 17:37:50 INFO Received uploads request method=POST path=/api/pending_closures993--- PASS: TestReadProxyContentNegotiation (0.66s)994=== CONT TestMultipartCleanup995--- PASS: TestReadProxyNarStreaming (0.77s)996=== CONT TestServerTLSConfig997=== RUN TestServerTLSConfig/no_client_CA998=== PAUSE TestServerTLSConfig/no_client_CA999=== RUN TestServerTLSConfig/missing_CA_file1000=== PAUSE TestServerTLSConfig/missing_CA_file1001=== RUN TestServerTLSConfig/not_a_PEM_file1002=== PAUSE TestServerTLSConfig/not_a_PEM_file1003=== CONT TestService_NativeMTLS10042026/10/09 17:37:50 INFO Received push request method=POST path=/api/pushes10052026/10/09 17:37:50 INFO Received uploads request method=POST path=/api/pending_closures10062026/10/09 17:37:50 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1007--- PASS: TestReadProxyNarinfo (0.77s)1008=== CONT TestMetricsCommit10092026-10-09 17:37:50.932 UTC [714] ERROR: could not obtain lock on row in relation "closures"10102026-10-09 17:37:50.932 UTC [714] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10112026-10-09 17:37:50.934 UTC [714] ERROR: could not obtain lock on row in relation "closures"10122026-10-09 17:37:50.934 UTC [714] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10132026-10-09 17:37:50.934 UTC [714] ERROR: could not obtain lock on row in relation "closures"10142026-10-09 17:37:50.934 UTC [714] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10152026-10-09 17:37:50.934 UTC [714] ERROR: could not obtain lock on row in relation "closures"10162026-10-09 17:37:50.934 UTC [714] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10172026-10-09 17:37:50.935 UTC [714] ERROR: could not obtain lock on row in relation "closures"10182026-10-09 17:37:50.935 UTC [714] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1019--- PASS: TestPush_RootsAreLockedInByteOrder (0.85s)1020=== CONT TestMetricsInventory10212026/10/09 17:37:50 INFO Received uploads request method=POST path=/api/pending_closures10222026/10/09 17:37:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10232026/10/09 17:37:50 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzA1ZWFhYWEtOTEwMy00MjI2LWE1NjQtZWU5M2Q5ZTZjOTVmLjk1MjZlMjc1LTM0ZjQtNDE4NS04MzAyLTljZTE0ZWMwNmI3ZngxNzkxNTY3NDcwOTIyMzczOTg510242026/10/09 17:37:50 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MzA1ZWFhYWEtOTEwMy00MjI2LWE1NjQtZWU5M2Q5ZTZjOTVmLjk1MjZlMjc1LTM0ZjQtNDE4NS04MzAyLTljZTE0ZWMwNmI3ZngxNzkxNTY3NDcwOTIyMzczOTg5 parts=11025--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.89s)1026=== CONT TestNARDeduplicationMetadataUploadBug1027--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.82s)1028=== CONT TestCreatePendingClosureRejectsOversizedNAR10292026/10/09 17:37:50 INFO Received uploads request method=POST path=/api/pending_closures1030--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1031=== CONT TestCacheConfigHandlerMaxNarSize1032--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1033=== CONT TestGenerateLandingPage1034--- PASS: TestGenerateLandingPage (0.00s)1035=== CONT TestService_readinessHandler10362026/10/09 17:37:50 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10372026/10/09 17:37:51 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MzA1ZWFhYWEtOTEwMy00MjI2LWE1NjQtZWU5M2Q5ZTZjOTVmLjMyMjA2YTk1LTU4YzYtNDQ5Yy04MWMxLTAzNGNjN2Y3OTIxOXgxNzkxNTY3NDcwNTYxMjg0ODcy parts=1010382026/10/09 17:37:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10392026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures1040--- PASS: TestPresentRefreshesOnlyStaleClosures (0.88s)1041=== CONT TestService_healthCheckHandler10422026/10/09 17:37:51 INFO Completed upload id=1 objects=2 duration=5.807678ms10432026/10/09 17:37:51 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010442026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures10452026/10/09 17:37:51 INFO Starting cleanup of old closures method=DELETE path=/api/closures10462026/10/09 17:37:51 INFO Aborted multipart uploads count=0 kept=010472026/10/09 17:37:51 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10482026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures10492026/10/09 17:37:51 INFO Received push request method=POST path=/api/pushes10502026/10/09 17:37:51 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=01051--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.98s)1052=== CONT TestGracefulShutdownDrainsInflight10532026/10/09 17:37:51 INFO Starting HTTP server address=127.0.0.1:4249710542026/10/09 17:37:51 INFO Shutdown signal received, draining in-flight requests timeout=10s10552026/10/09 17:37:51 INFO Vacuumed table table=pending_closures10562026/10/09 17:37:51 INFO Vacuumed table table=pending_objects10572026/10/09 17:37:51 INFO Vacuumed table table=multipart_uploads10582026/10/09 17:37:51 INFO Vacuumed table table=closures10592026/10/09 17:37:51 INFO Vacuumed table table=objects10602026-10-09 17:37:51.088 UTC [697] ERROR: Push does not exist: id=110612026-10-09 17:37:51.088 UTC [697] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE10622026-10-09 17:37:51.088 UTC [697] STATEMENT: SELECT commit_push($1)1063--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.99s)1064=== CONT TestGCTaskStore_Fail1065--- PASS: TestGCTaskStore_Fail (0.00s)1066=== CONT TestGCTaskStore_PhaseUpdates1067--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1068=== CONT TestGCTaskStore_CompletedAllowsNewTask1069--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1070=== CONT TestGCTaskStore_GetReturnsLatest1071--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1072=== CONT TestGCTaskStore_GetEmpty1073--- PASS: TestGCTaskStore_GetEmpty (0.00s)1074=== CONT TestGCTaskStore_ConflictDifferentParams1075--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1076=== CONT TestGCTaskStore_DeduplicateSameParams1077--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1078=== CONT TestGCTaskStore_StartNew1079--- PASS: TestGCTaskStore_StartNew (0.00s)1080=== CONT TestGCEndsOnShutdown1081=== RUN TestGCEndsOnShutdown/before_the_run1082=== PAUSE TestGCEndsOnShutdown/before_the_run1083=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1084=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1085=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1086=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1087=== CONT TestCommitRacingPendingCleanupKeepsObjects10882026/10/09 17:37:51 INFO Received complete push request method=POST path=/api/pushes/1/complete10892026/10/09 17:37:51 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001090--- PASS: TestService_createPendingClosureHandler (1.01s)1091=== CONT TestPushWaitsForSweepHoldingRow10922026/10/09 17:37:51 INFO Completed push id=1 objects=4 duration=10.933157ms10932026/10/09 17:37:51 INFO Received push request method=POST path=/api/pushes1094--- PASS: TestPresentReportsOnlyClosureRoots (0.88s)1095=== CONT TestSweepRechecksPendingAfterLocking1096--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1097=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1098--- PASS: TestGetExistingObjectsLocksRows (1.00s)1099=== CONT TestClientCADerivations11002026/10/09 17:37:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11012026/10/09 17:37:51 INFO Aborted multipart uploads count=0 kept=011022026/10/09 17:37:51 WARN Force mode enabled - objects will be deleted immediately without grace period11032026/10/09 17:37:51 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11042026/10/09 17:37:51 WARN Refused reserved pin name=worker-x86_64-linux11052026/10/09 17:37:51 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11062026/10/09 17:37:51 INFO Received create pin request method=POST path=/api/pins/my-app11072026/10/09 17:37:51 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1108--- PASS: TestCreatePin_ReservedPins (0.66s)1109=== CONT TestRegisterCompletedObjectNeedsPendingRow11102026/10/09 17:37:51 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MzA1ZWFhYWEtOTEwMy00MjI2LWE1NjQtZWU5M2Q5ZTZjOTVmLmY2NTBmM2NhLTcwYTUtNDUzZC1hOGZlLTU2NTIwYzYyNGU4YngxNzkxNTY3NDcwNzIzMTUzNDI0 parts=1011112026/10/09 17:37:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11122026/10/09 17:37:51 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=011132026/10/09 17:37:51 INFO Completed upload id=1 objects=2 duration=6.226987ms11142026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures11152026/10/09 17:37:51 INFO Vacuumed table table=pending_closures11162026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures11172026/10/09 17:37:51 INFO Vacuumed table table=pending_objects11182026/10/09 17:37:51 INFO Vacuumed table table=multipart_uploads11192026/10/09 17:37:51 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11202026/10/09 17:37:51 WARN Found objects in DB but missing from S3, will re-upload count=11121--- PASS: TestService_verifyS3Integrity (1.12s)1122=== CONT TestDeleteClosuresRacingPins11232026/10/09 17:37:51 INFO Vacuumed table table=closures11242026/10/09 17:37:51 INFO Vacuumed table table=objects11252026/10/09 17:37:51 INFO Received complete push request method=POST path=/api/pushes/2/complete11262026/10/09 17:37:51 INFO Completed push id=2 objects=4 duration=6.065877ms1127--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.16s)1128=== CONT TestSweepSkipsRowsLockedByPush11292026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures1130--- PASS: TestObjectStatsTrigger (0.64s)1131=== CONT TestClientFallsBackToClosures11322026/10/09 17:37:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11332026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures11342026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures11352026/10/09 17:37:51 INFO Received cleanup request method=DELETE path=/api/pending_closures11362026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures11372026/10/09 17:37:51 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MzA1ZWFhYWEtOTEwMy00MjI2LWE1NjQtZWU5M2Q5ZTZjOTVmLjIyOWFmMjExLWY3ZWQtNGFmZS1iYzkwLTI2NzA2OTBhNmVmMHgxNzkxNTY3NDcwODA2NTExOTQ0 parts=121138--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.66s)11392026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures1140=== CONT TestFailedS3DeleteKeepsTombstone11412026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures11422026/10/09 17:37:51 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11432026/10/09 17:37:51 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1144--- PASS: TestService_NativeMTLS (0.50s)1145=== CONT TestClientPushesUseOnePush11462026/10/09 17:37:51 INFO Received push request method=POST path=/api/pushes11472026/10/09 17:37:51 INFO Received complete push request method=POST path=/api/pushes/1/complete11482026/10/09 17:37:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11492026/10/09 17:37:51 INFO Completed push id=1 objects=4 duration=9.390551ms1150--- PASS: TestMetricsInventory (0.51s)1151=== CONT TestForceGCDuringPushOffersSweptObject1152=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1153=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1154=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1155=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1156=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection11572026/10/09 17:37:51 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11582026/10/09 17:37:51 INFO Completed upload id=2 objects=2 duration=1.518117ms1159--- PASS: TestMetricsCommit (0.53s)1160=== CONT TestGCSweepDeliversEachKeyOnce11612026/10/09 17:37:51 INFO Received cleanup request method=DELETE path=/api/pending_closures11622026/10/09 17:37:51 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket35/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""11632026/10/09 17:37:51 INFO Aborted multipart uploads count=0 kept=111642026/10/09 17:37:51 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MzA1ZWFhYWEtOTEwMy00MjI2LWE1NjQtZWU5M2Q5ZTZjOTVmLjVlM2U2ZWVkLTIyMWMtNDA1Zi05Yjg0LTA5NGIyOTkwNDhlNngxNzkxNTY3NDcwOTU1MzgwMzAy parts=1211652026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures1166--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.38s)11672026/10/09 17:37:51 INFO Received cleanup request method=DELETE path=/api/pending_closures1168=== CONT TestTombstonedObjectOfferedWithoutWaiting11692026/10/09 17:37:51 INFO Aborted multipart uploads count=1 kept=01170--- PASS: TestMultipartCleanup (0.66s)1171=== CONT TestPinProtectsFromGC11722026/10/09 17:37:51 WARN readiness check failed error="closed pool"1173--- PASS: TestService_readinessHandler (0.52s)1174=== CONT TestGCSweepSkipsPendingObjects1175=== NAME TestNARDeduplicationMetadataUploadBug1176 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1481498272/001/store/z7kiz3cwpqyshz2xs8k1qxl8lsracj3c-file1.txt1177--- PASS: TestService_healthCheckHandler (0.49s)1178=== CONT TestClientSharedPathCommittedMidPush11792026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures1180=== NAME TestOrphanedObjectsGC1181 orphaned_objects_gc_test.go:287: GC Test Summary:1182 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1183 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1184 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1185 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1186 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1187--- PASS: TestOrphanedObjectsGC (0.99s)1188=== CONT TestDeduplicatedObjectsRecordedAsPending11892026/10/09 17:37:51 INFO Aborted multipart uploads count=0 kept=011902026/10/09 17:37:51 INFO Received push request method=POST path=/api/pushes11912026/10/09 17:37:51 INFO Aborted multipart uploads count=0 kept=011922026/10/09 17:37:51 WARN Force mode enabled - objects will be deleted immediately without grace period11932026/10/09 17:37:51 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11942026/10/09 17:37:51 INFO Uploading z7kiz3cwpqyshz2xs8k1qxl8lsracj3c-file1.txt (160B)11952026/10/09 17:37:51 WARN Force mode enabled - objects will be deleted immediately without grace period11962026/10/09 17:37:51 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=011972026/10/09 17:37:51 WARN Failed to register uploaded object key=z7kiz3cwpqyshz2xs8k1qxl8lsracj3c.ls error="server returned 404: 404 page not found\n"11982026/10/09 17:37:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11992026/10/09 17:37:51 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12002026/10/09 17:37:51 INFO Signed narinfos id=1 count=112012026/10/09 17:37:51 INFO Uploading 1 narinfos12022026/10/09 17:37:51 INFO Vacuumed table table=pending_closures12032026/10/09 17:37:51 INFO Received complete push request method=POST path=/api/pushes/1/complete12042026/10/09 17:37:51 WARN Failed to register uploaded object key=z7kiz3cwpqyshz2xs8k1qxl8lsracj3c.narinfo error="server returned 404: 404 page not found\n"12052026/10/09 17:37:51 INFO Vacuumed table table=pending_objects12062026/10/09 17:37:51 INFO Vacuumed table table=multipart_uploads12072026/10/09 17:37:51 INFO Vacuumed table table=closures12082026/10/09 17:37:51 INFO Vacuumed table table=objects12092026/10/09 17:37:51 INFO Completed push id=1 objects=3 duration=6.764057ms12102026/10/09 17:37:51 INFO Upload complete. (73ms)12112026/10/09 17:37:51 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=01212=== NAME TestNARDeduplicationMetadataUploadBug1213 metadata_upload_test.go:54: Retrieved narinfo from S3:1214 StorePath: /build/TestNARDeduplicationMetadataUploadBug1481498272/001/store/z7kiz3cwpqyshz2xs8k1qxl8lsracj3c-file1.txt1215 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1216 Compression: zstd1217 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1218 NarSize: 1601219 References: 1220 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf12212026/10/09 17:37:51 INFO Vacuumed table table=pending_closures1222 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1223 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1224 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1225--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.56s)1226=== CONT TestClientWithDependencies12272026/10/09 17:37:51 INFO Vacuumed table table=pending_objects12282026/10/09 17:37:51 INFO Vacuumed table table=multipart_uploads12292026/10/09 17:37:51 INFO Vacuumed table table=closures12302026/10/09 17:37:51 INFO Vacuumed table table=objects1231--- PASS: TestSweepRechecksPendingAfterLocking (0.53s)1232=== CONT TestPushDedupSurvivesConcurrentGC1233--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.48s)1234=== CONT TestClientMultipleUploads1235=== NAME TestNARDeduplicationMetadataUploadBug1236 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1481498272/001/store/b194wi6pjbzf7n76y4i9fa3i3zhsh525-file2.txt12372026/10/09 17:37:51 INFO Aborted multipart uploads count=0 kept=012382026/10/09 17:37:51 WARN Force mode enabled - objects will be deleted immediately without grace period12392026/10/09 17:37:51 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=012402026/10/09 17:37:51 INFO Vacuumed table table=pending_closures12412026/10/09 17:37:51 INFO Vacuumed table table=pending_objects12422026/10/09 17:37:51 INFO Vacuumed table table=multipart_uploads12432026/10/09 17:37:51 INFO Vacuumed table table=closures12442026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures12452026/10/09 17:37:51 INFO Vacuumed table table=objects12462026/10/09 17:37:51 INFO Received push request method=POST path=/api/pushes1247=== NAME TestClientCADerivations1248 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3416390694/001/store/37ja3wfnxr9mjzvjwda3lzzvf5vpri66-ca-test12492026/10/09 17:37:51 INFO Aborted multipart uploads count=0 kept=012502026/10/09 17:37:51 WARN Force mode enabled - objects will be deleted immediately without grace period12512026/10/09 17:37:51 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=012522026/10/09 17:37:51 INFO Vacuumed table table=pending_closures12532026/10/09 17:37:51 INFO Vacuumed table table=pending_objects12542026/10/09 17:37:51 INFO Vacuumed table table=multipart_uploads12552026/10/09 17:37:51 INFO Vacuumed table table=closures12562026/10/09 17:37:51 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12572026/10/09 17:37:51 INFO Vacuumed table table=objects12582026/10/09 17:37:51 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1259--- PASS: TestSweepSkipsRowsLockedByPush (0.51s)1260=== CONT TestGCMetrics12612026/10/09 17:37:51 WARN Failed to register uploaded object key=b194wi6pjbzf7n76y4i9fa3i3zhsh525.ls error="server returned 404: 404 page not found\n"12622026/10/09 17:37:51 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12632026/10/09 17:37:51 INFO Signed narinfos id=2 count=112642026/10/09 17:37:51 INFO Uploading 1 narinfos12652026/10/09 17:37:51 INFO Received complete push request method=POST path=/api/pushes/2/complete12662026/10/09 17:37:51 WARN Failed to register uploaded object key=b194wi6pjbzf7n76y4i9fa3i3zhsh525.narinfo error="server returned 404: 404 page not found\n"12672026/10/09 17:37:51 INFO Completed push id=2 objects=3 duration=2.467145ms12682026/10/09 17:37:51 INFO Upload complete. (65ms)1269=== NAME TestNARDeduplicationMetadataUploadBug1270 metadata_upload_test.go:76: Retrieved narinfo from S3:1271 StorePath: /build/TestNARDeduplicationMetadataUploadBug1481498272/001/store/b194wi6pjbzf7n76y4i9fa3i3zhsh525-file2.txt1272 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1273 Compression: zstd1274 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1275 NarSize: 1601276 References: 1277 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1278=== NAME TestClientCADerivations1279 client_ca_test.go:139: Found 1 dependencies (including self)1280=== NAME TestNARDeduplicationMetadataUploadBug1281 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1282 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1283 {"version":1,"root":{"type":"regular","size":44}}12842026/10/09 17:37:51 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MzA1ZWFhYWEtOTEwMy00MjI2LWE1NjQtZWU5M2Q5ZTZjOTVmLjY1MDA0MWNiLTRiNTEtNDQ0Yi1iNzNkLTNmYzIxYzQ3ZDc5NHgxNzkxNTY3NDcxMzU1OTI2NTE5 error="Get \"http://127.0.0.1:1/bucket16/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"12852026/10/09 17:37:51 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MzA1ZWFhYWEtOTEwMy00MjI2LWE1NjQtZWU5M2Q5ZTZjOTVmLmQ5YmRkMzQzLWQwM2UtNDI1ZS1hYzMxLTEyZDczY2VhODRmN3gxNzkxNTY3NDcxMzQ5MDQyMDIz parts=1212862026/10/09 17:37:51 INFO Received cleanup request method=DELETE path=/api/pending_closures1287--- PASS: TestNARDeduplicationMetadataUploadBug (0.81s)1288=== CONT TestClientIntegration12892026/10/09 17:37:51 INFO Aborted multipart uploads count=1 kept=01290--- PASS: TestRedundantMultipartUpload (1.71s)1291=== CONT TestGCBugBareHashReferences12922026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures12932026/10/09 17:37:51 INFO Aborted multipart uploads count=0 kept=012942026/10/09 17:37:51 WARN Force mode enabled - objects will be deleted immediately without grace period12952026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures12962026/10/09 17:37:51 INFO Aborted multipart uploads count=0 kept=012972026/10/09 17:37:51 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=012982026/10/09 17:37:51 INFO Vacuumed table table=pending_closures1299--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.36s)1300=== CONT TestClientErrorHandling13012026/10/09 17:37:51 INFO Vacuumed table table=pending_objects1302=== RUN TestClientErrorHandling/InvalidStorePath1303=== PAUSE TestClientErrorHandling/InvalidStorePath1304=== RUN TestClientErrorHandling/InvalidAuthToken1305=== PAUSE TestClientErrorHandling/InvalidAuthToken1306=== RUN TestClientErrorHandling/ServerNotAvailable13072026/10/09 17:37:51 INFO Vacuumed table table=multipart_uploads1308=== PAUSE TestClientErrorHandling/ServerNotAvailable1309=== CONT TestGCAdvisoryLockBlocksConcurrentRun13102026/10/09 17:37:51 INFO Vacuumed table table=closures13112026/10/09 17:37:51 WARN Force mode enabled - objects will be deleted immediately without grace period13122026/10/09 17:37:51 INFO Vacuumed table table=objects1313--- PASS: TestGCSweepDeliversEachKeyOnce (0.38s)1314=== CONT TestReadProxyDisabled13152026/10/09 17:37:51 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."13162026/10/09 17:37:51 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1317--- PASS: TestFailedS3DeleteKeepsTombstone (0.50s)1318=== CONT TestLeadEndsOnShutdown13192026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures13202026/10/09 17:37:51 INFO Aborted multipart uploads count=0 kept=013212026/10/09 17:37:51 INFO Received push request method=POST path=/api/pushes13222026/10/09 17:37:51 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13232026/10/09 17:37:51 INFO Uploading 37ja3wfnxr9mjzvjwda3lzzvf5vpri66-ca-test (144B)13242026/10/09 17:37:51 WARN Force mode enabled - objects will be deleted immediately without grace period13252026/10/09 17:37:51 WARN Failed to register uploaded object key=37ja3wfnxr9mjzvjwda3lzzvf5vpri66.ls error="server returned 404: 404 page not found\n"13262026/10/09 17:37:51 WARN Failed to register uploaded object key=log/l8ci5q9r79czrg7njrp6gq9p9lm2igkr-ca-test.drv error="server returned 404: 404 page not found\n"13272026/10/09 17:37:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13282026/10/09 17:37:51 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"13292026/10/09 17:37:51 INFO Signed narinfos id=1 count=113302026/10/09 17:37:51 INFO Uploading 1 narinfos13312026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures13322026/10/09 17:37:51 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=013332026/10/09 17:37:51 INFO Received complete push request method=POST path=/api/pushes/1/complete13342026/10/09 17:37:51 WARN Failed to register uploaded object key=37ja3wfnxr9mjzvjwda3lzzvf5vpri66.narinfo error="server returned 404: 404 page not found\n"1335=== NAME TestPinProtectsFromGC1336 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC2837679242/001/store/8hg57ah1h080y9m36sghqdhcxlah6ys6-pinned-file.txt1337 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC2837679242/001/store/gqmlcqwm929j1yh6kayww0j56xqdkl1s-unpinned-file.txt13382026/10/09 17:37:51 INFO Completed push id=1 objects=4 duration=20.212339ms1339--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.79s)13402026/10/09 17:37:51 INFO Upload complete. (111ms)1341=== CONT TestPush_CompleteCommitsEveryRoot13422026/10/09 17:37:51 INFO Vacuumed table table=pending_closures1343--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.34s)1344=== CONT TestLeadIncumbentAnnouncesAtOnce1345=== NAME TestClientCADerivations1346 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3416390694/001/store/37ja3wfnxr9mjzvjwda3lzzvf5vpri66-ca-test1347 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1348 Compression: zstd1349 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1350 NarSize: 1441351 References: 1352 Deriver: /build/TestClientCADerivations3416390694/001/store/l8ci5q9r79czrg7njrp6gq9p9lm2igkr-ca-test.drv1353 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1354 client_ca_test.go:185: Checking for realisation files in S3...13552026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures1356 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1357 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache13582026/10/09 17:37:51 INFO Vacuumed table table=pending_objects13592026/10/09 17:37:51 INFO Vacuumed table table=multipart_uploads13602026/10/09 17:37:51 INFO Vacuumed table table=closures13612026/10/09 17:37:51 INFO Vacuumed table table=objects13622026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures13632026/10/09 17:37:51 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13642026/10/09 17:37:51 INFO Uploading 5hpwm31wb2a253z4sqj5vy51qnig2ns5-shared-dep (136B)13652026/10/09 17:37:51 INFO Uploading j2fqggl0x79yfjb41h8si5sp0c77wa91-a (216B)13662026/10/09 17:37:51 WARN Failed to register uploaded object key=0gina72nj6skgbndaq44vqq8y223iw1s.ls error="server returned 404: 404 page not found\n"13672026/10/09 17:37:51 WARN Failed to register uploaded object key=5hpwm31wb2a253z4sqj5vy51qnig2ns5.ls error="server returned 404: 404 page not found\n"13682026/10/09 17:37:51 WARN Failed to register uploaded object key=j2fqggl0x79yfjb41h8si5sp0c77wa91.ls error="server returned 404: 404 page not found\n"13692026/10/09 17:37:51 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13702026/10/09 17:37:51 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13712026/10/09 17:37:51 WARN Failed to register uploaded object key=nar/1cv2x3kr80xfsa4lz7w8w0841xm0frmbq3pk04s2i3vxp4glzhmg.nar.zst error="server returned 404: 404 page not found\n"13722026/10/09 17:37:51 INFO Signed narinfos id=2 count=213732026/10/09 17:37:51 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13742026/10/09 17:37:51 INFO Signed narinfos id=1 count=213752026/10/09 17:37:51 INFO Uploading 4 narinfos1376--- PASS: TestGCSweepSkipsPendingObjects (0.45s)1377=== CONT TestPush_OverlappingRootsStoreOneRowPerKey13782026/10/09 17:37:51 WARN Failed to register uploaded object key=j2fqggl0x79yfjb41h8si5sp0c77wa91.narinfo error="server returned 404: 404 page not found\n"13792026/10/09 17:37:51 WARN Failed to register uploaded object key=0gina72nj6skgbndaq44vqq8y223iw1s.narinfo error="server returned 404: 404 page not found\n"13802026/10/09 17:37:51 WARN Failed to register uploaded object key=5hpwm31wb2a253z4sqj5vy51qnig2ns5.narinfo error="server returned 404: 404 page not found\n"13812026/10/09 17:37:51 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13822026/10/09 17:37:51 WARN Failed to register uploaded object key=5hpwm31wb2a253z4sqj5vy51qnig2ns5.narinfo error="server returned 404: 404 page not found\n"13832026/10/09 17:37:51 INFO Received push request method=POST path=/api/pushes13842026/10/09 17:37:51 INFO Completed upload id=1 objects=6 duration=8.828992ms13852026/10/09 17:37:51 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13862026/10/09 17:37:51 INFO Completed upload id=2 objects=6 duration=2.730215ms13872026/10/09 17:37:51 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13882026/10/09 17:37:51 INFO Uploading cqyh44sr5y8af3jrzlrj5nim7a241180-b (216B)13892026/10/09 17:37:51 INFO Upload complete. (84ms)13902026/10/09 17:37:51 INFO Uploading 9mq3i6cqw6f7j6wrs2hhjhbw82x1mv0s-shared-dep (136B)1391=== NAME TestClientFallsBackToClosures1392 client_pushes_test.go:112: Retrieved narinfo from S3:1393 StorePath: /build/TestClientFallsBackToClosures4151165603/001/store/5hpwm31wb2a253z4sqj5vy51qnig2ns5-shared-dep1394 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1395 Compression: zstd1396 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821397 NarSize: 1361398 References: 1399 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n14002026/10/09 17:37:51 WARN Failed to register uploaded object key=b1k27gmbahldxzb4s70xz3xmygm1scnw.ls error="server returned 404: 404 page not found\n"1401 client_pushes_test.go:112: Retrieved narinfo from S3:14022026/10/09 17:37:51 WARN Failed to register uploaded object key=nar/17qhmjy2gldi9s1k1cq1jgj310y2vknkpaqzvb4m54rv7i9v3x45.nar.zst error="server returned 404: 404 page not found\n"1403 StorePath: /build/TestClientFallsBackToClosures4151165603/001/store/j2fqggl0x79yfjb41h8si5sp0c77wa91-a14042026/10/09 17:37:51 WARN Failed to register uploaded object key=cqyh44sr5y8af3jrzlrj5nim7a241180.ls error="server returned 404: 404 page not found\n"1405 URL: nar/1cv2x3kr80xfsa4lz7w8w0841xm0frmbq3pk04s2i3vxp4glzhmg.nar.zst1406 Compression: zstd1407 NarHash: sha256:1cv2x3kr80xfsa4lz7w8w0841xm0frmbq3pk04s2i3vxp4glzhmg1408 NarSize: 2161409 References: /build/TestClientFallsBackToClosures4151165603/001/store/5hpwm31wb2a253z4sqj5vy51qnig2ns5-shared-dep1410 CA: text:sha256:1bign6p5alc9yijnnp07zra23w4g6nmwbsdcl1h933ynw818s8bh14112026/10/09 17:37:51 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1412 client_pushes_test.go:112: Retrieved narinfo from S3:14132026/10/09 17:37:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1414 StorePath: /build/TestClientFallsBackToClosures4151165603/001/store/0gina72nj6skgbndaq44vqq8y223iw1s-b1415 URL: nar/1cv2x3kr80xfsa4lz7w8w0841xm0frmbq3pk04s2i3vxp4glzhmg.nar.zst14162026/10/09 17:37:51 WARN Failed to register uploaded object key=9mq3i6cqw6f7j6wrs2hhjhbw82x1mv0s.ls error="server returned 404: 404 page not found\n"1417 Compression: zstd1418 NarHash: sha256:1cv2x3kr80xfsa4lz7w8w0841xm0frmbq3pk04s2i3vxp4glzhmg1419 NarSize: 2161420 References: /build/TestClientFallsBackToClosures4151165603/001/store/5hpwm31wb2a253z4sqj5vy51qnig2ns5-shared-dep1421 CA: text:sha256:1bign6p5alc9yijnnp07zra23w4g6nmwbsdcl1h933ynw818s8bh14222026/10/09 17:37:51 INFO Signed narinfos id=1 count=314232026/10/09 17:37:51 INFO Uploading 3 narinfos14242026/10/09 17:37:51 WARN Failed to register uploaded object key=9mq3i6cqw6f7j6wrs2hhjhbw82x1mv0s.narinfo error="server returned 404: 404 page not found\n"14252026/10/09 17:37:51 WARN Failed to register uploaded object key=b1k27gmbahldxzb4s70xz3xmygm1scnw.narinfo error="server returned 404: 404 page not found\n"14262026/10/09 17:37:51 INFO Received complete push request method=POST path=/api/pushes/1/complete14272026/10/09 17:37:51 WARN Failed to register uploaded object key=cqyh44sr5y8af3jrzlrj5nim7a241180.narinfo error="server returned 404: 404 page not found\n"14282026/10/09 17:37:51 INFO Received uploads request method=POST path=/api/pending_closures1429--- PASS: TestClientFallsBackToClosures (0.70s)1430=== CONT TestLeadScopedToFarm1431=== NAME TestClientMultipleUploads1432 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads1319246349/001/store/8hqjnki8fhagfifdbrm5m3nc49v7ykbm-test-file-0.txt14332026/10/09 17:37:52 INFO Aborted multipart uploads count=0 kept=014342026/10/09 17:37:52 INFO Completed push id=1 objects=8 duration=17.406274ms14352026/10/09 17:37:52 INFO Upload complete. (86ms)1436=== NAME TestClientPushesUseOnePush1437 client_pushes_test.go:97: Retrieved narinfo from S3:1438 StorePath: /build/TestClientPushesUseOnePush2702364930/001/store/9mq3i6cqw6f7j6wrs2hhjhbw82x1mv0s-shared-dep1439 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1440 Compression: zstd1441 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821442 NarSize: 1361443 References: 1444 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1445 client_pushes_test.go:97: Retrieved narinfo from S3:1446 StorePath: /build/TestClientPushesUseOnePush2702364930/001/store/b1k27gmbahldxzb4s70xz3xmygm1scnw-a1447 URL: nar/17qhmjy2gldi9s1k1cq1jgj310y2vknkpaqzvb4m54rv7i9v3x45.nar.zst1448 Compression: zstd1449 NarHash: sha256:17qhmjy2gldi9s1k1cq1jgj310y2vknkpaqzvb4m54rv7i9v3x451450 NarSize: 2161451 References: /build/TestClientPushesUseOnePush2702364930/001/store/9mq3i6cqw6f7j6wrs2hhjhbw82x1mv0s-shared-dep1452 CA: text:sha256:0d850183a9bjmfa45h7kmlyxxas8wyir0axh0ky9ymxpfdzhd70p14532026/10/09 17:37:52 INFO Received push request method=POST path=/api/pushes14542026/10/09 17:37:52 WARN Force mode enabled - objects will be deleted immediately without grace period1455 client_pushes_test.go:97: Retrieved narinfo from S3:1456 StorePath: /build/TestClientPushesUseOnePush2702364930/001/store/cqyh44sr5y8af3jrzlrj5nim7a241180-b1457 URL: nar/17qhmjy2gldi9s1k1cq1jgj310y2vknkpaqzvb4m54rv7i9v3x45.nar.zst1458 Compression: zstd1459 NarHash: sha256:17qhmjy2gldi9s1k1cq1jgj310y2vknkpaqzvb4m54rv7i9v3x451460 NarSize: 2161461 References: /build/TestClientPushesUseOnePush2702364930/001/store/9mq3i6cqw6f7j6wrs2hhjhbw82x1mv0s-shared-dep1462 CA: text:sha256:0d850183a9bjmfa45h7kmlyxxas8wyir0axh0ky9ymxpfdzhd70p14632026/10/09 17:37:52 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014642026/10/09 17:37:52 INFO Vacuumed table table=pending_closures14652026/10/09 17:37:52 INFO Vacuumed table table=pending_objects14662026/10/09 17:37:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14672026/10/09 17:37:52 INFO Uploading 8hg57ah1h080y9m36sghqdhcxlah6ys6-pinned-file.txt (128B)14682026/10/09 17:37:52 INFO Vacuumed table table=multipart_uploads14692026/10/09 17:37:52 INFO Vacuumed table table=closures1470--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.57s)1471=== CONT TestReadRedirectUsesPublicS3URL14722026/10/09 17:37:52 INFO Vacuumed table table=objects1473--- PASS: TestClientPushesUseOnePush (0.65s)1474=== CONT TestLeadElectsOneAndHandsOver14752026/10/09 17:37:52 WARN Failed to register uploaded object key=8hg57ah1h080y9m36sghqdhcxlah6ys6.ls error="server returned 404: 404 page not found\n"14762026/10/09 17:37:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14772026/10/09 17:37:52 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14782026/10/09 17:37:52 INFO Signed narinfos id=1 count=114792026/10/09 17:37:52 INFO Uploading 1 narinfos14802026/10/09 17:37:52 INFO Received complete push request method=POST path=/api/pushes/1/complete14812026/10/09 17:37:52 WARN Failed to register uploaded object key=8hg57ah1h080y9m36sghqdhcxlah6ys6.narinfo error="server returned 404: 404 page not found\n"1482=== NAME TestClientWithDependencies1483 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies3262926552/001/store/rz58jvjrplw5b87px2h0zf0jgc77pxq6-test-script1484--- PASS: TestGCMetrics (0.25s)1485=== CONT TestReadProxyRangeRequest1486=== NAME TestClientMultipleUploads1487 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads1319246349/001/store/6h0jnf08bp1yzgrxnbm276diagmiy5yh-test-file-1.txt14882026/10/09 17:37:52 INFO Completed push id=1 objects=3 duration=12.282665ms14892026/10/09 17:37:52 INFO Upload complete. (73ms)14902026/10/09 17:37:52 INFO Received push request method=POST path=/api/pushes14912026/10/09 17:37:52 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14922026/10/09 17:37:52 INFO Uploading zr0jm66nbcmam0b2a4gm46amslv6p6x8-top (224B)14932026/10/09 17:37:52 INFO Uploading k4r4wm0ighnnxz78i8vgiwa21m18bcbk-shared-dep (136B)1494=== NAME TestClientWithDependencies14952026/10/09 17:37:52 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1496 client_integration_test.go:615: Found 1 dependencies (including self)14972026/10/09 17:37:52 WARN Failed to register uploaded object key=k4r4wm0ighnnxz78i8vgiwa21m18bcbk.ls error="server returned 404: 404 page not found\n"14982026/10/09 17:37:52 WARN Failed to register uploaded object key=nar/0f5jvv7ags3xbrzmc3ak75lp7rw1dkjilqa0z6y8s7cg9a3zqwgn.nar.zst error="server returned 404: 404 page not found\n"14992026/10/09 17:37:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15002026/10/09 17:37:52 WARN Failed to register uploaded object key=zr0jm66nbcmam0b2a4gm46amslv6p6x8.ls error="server returned 404: 404 page not found\n"15012026/10/09 17:37:52 INFO Signed narinfos id=1 count=215022026/10/09 17:37:52 INFO Uploading 2 narinfos15032026/10/09 17:37:52 WARN Failed to register uploaded object key=zr0jm66nbcmam0b2a4gm46amslv6p6x8.narinfo error="server returned 404: 404 page not found\n"15042026/10/09 17:37:52 INFO Received complete push request method=POST path=/api/pushes/1/complete15052026/10/09 17:37:52 WARN Failed to register uploaded object key=k4r4wm0ighnnxz78i8vgiwa21m18bcbk.narinfo error="server returned 404: 404 page not found\n"15062026/10/09 17:37:52 INFO Aborted multipart uploads count=0 kept=01507=== NAME TestClientIntegration1508 client_integration_test.go:286: Created store path: /build/TestClientIntegration3210132810/002/store/a51y62wsvw4zmfjj596052jzbgkhvh3d-test-file.txt15092026/10/09 17:37:52 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=nixbld database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1510=== NAME TestClientCADerivations1511 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1512 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1513 error: binary cache 's3://bucket46?endpoint=http://localhost:43445&region=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3416390694/001/store'1514 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11515--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.23s)1516=== CONT TestConnectWaitsForAPeerMigration1517=== NAME TestClientMultipleUploads1518 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads1319246349/001/store/nm6pwm62dv8s80mraqsp3lxj97s15bxm-test-file-2.txt15192026/10/09 17:37:52 INFO Completed push id=1 objects=6 duration=12.787984ms15202026/10/09 17:37:52 INFO Upload complete. (70ms)1521=== NAME TestClientSharedPathCommittedMidPush1522 client_integration_test.go:680: Retrieved narinfo from S3:1523 StorePath: /build/TestClientSharedPathCommittedMidPush3402803567/001/store/k4r4wm0ighnnxz78i8vgiwa21m18bcbk-shared-dep1524 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1525 Compression: zstd1526 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821527 NarSize: 1361528 References: 1529 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1530--- PASS: TestClientCADerivations (0.92s)1531=== CONT TestResolveDBConnectionString1532=== RUN TestResolveDBConnectionString/flag_wins1533=== PAUSE TestResolveDBConnectionString/flag_wins1534=== RUN TestResolveDBConnectionString/file_when_flag_empty1535=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1536=== RUN TestResolveDBConnectionString/missing_file_is_an_error1537=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1538=== NAME TestClientSharedPathCommittedMidPush1539 client_integration_test.go:680: Retrieved narinfo from S3:1540 StorePath: /build/TestClientSharedPathCommittedMidPush3402803567/001/store/zr0jm66nbcmam0b2a4gm46amslv6p6x8-top1541 URL: nar/0f5jvv7ags3xbrzmc3ak75lp7rw1dkjilqa0z6y8s7cg9a3zqwgn.nar.zst1542 Compression: zstd1543 NarHash: sha256:0f5jvv7ags3xbrzmc3ak75lp7rw1dkjilqa0z6y8s7cg9a3zqwgn1544 NarSize: 2241545 References: /build/TestClientSharedPathCommittedMidPush3402803567/001/store/k4r4wm0ighnnxz78i8vgiwa21m18bcbk-shared-dep1546 CA: text:sha256:064x177w8bx9ri9jazq4fkbyq7cwa4r8m3ivipln5m7h8p9j0hkp1547=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1548=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1549=== RUN TestResolveDBConnectionString/nothing_configured1550=== PAUSE TestResolveDBConnectionString/nothing_configured1551=== CONT TestReadRedirectKeepsNarinfoProxied15522026/10/09 17:37:52 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=015532026/10/09 17:37:52 INFO lead: acquired remote=192.0.2.1:12341554--- PASS: TestClientSharedPathCommittedMidPush (0.55s)1555=== CONT TestReadRedirectNar15562026/10/09 17:37:52 INFO Vacuumed table table=pending_closures15572026/10/09 17:37:52 INFO Vacuumed table table=pending_objects15582026/10/09 17:37:52 INFO Vacuumed table table=multipart_uploads15592026/10/09 17:37:52 INFO Vacuumed table table=closures15602026/10/09 17:37:52 INFO Vacuumed table table=objects1561--- PASS: TestPushWaitsForSweepHoldingRow (0.99s)1562=== CONT TestReadProxyOutlastsServerWriteTimeout15632026/10/09 17:37:52 INFO Aborted multipart uploads count=0 kept=015642026/10/09 17:37:52 WARN Force mode enabled - objects will be deleted immediately without grace period1565--- PASS: TestReadProxyDisabled (0.26s)1566=== CONT TestReadProxyRootRedirectsToIndexHTML15672026/10/09 17:37:52 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=015682026/10/09 17:37:52 INFO Vacuumed table table=pending_closures15692026/10/09 17:37:52 INFO Vacuumed table table=pending_objects15702026/10/09 17:37:52 INFO Vacuumed table table=multipart_uploads15712026/10/09 17:37:52 INFO Vacuumed table table=closures15722026/10/09 17:37:52 INFO Vacuumed table table=objects1573--- PASS: TestPushDedupSurvivesConcurrentGC (0.46s)1574=== CONT TestService_AuthMiddleware_OIDC15752026/10/09 17:37:52 INFO Received push request method=POST path=/api/pushes15762026/10/09 17:37:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15772026/10/09 17:37:52 INFO Uploading gqmlcqwm929j1yh6kayww0j56xqdkl1s-unpinned-file.txt (128B)15782026/10/09 17:37:52 INFO Received push request method=POST path=/api/pushes15792026/10/09 17:37:52 WARN Failed to register uploaded object key=gqmlcqwm929j1yh6kayww0j56xqdkl1s.ls error="server returned 404: 404 page not found\n"15802026/10/09 17:37:52 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15812026/10/09 17:37:52 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"15822026/10/09 17:37:52 INFO Signed narinfos id=2 count=115832026/10/09 17:37:52 INFO Uploading 1 narinfos15842026/10/09 17:37:52 INFO Received push request method=POST path=/api/pushes15852026/10/09 17:37:52 INFO Received complete push request method=POST path=/api/pushes/2/complete15862026/10/09 17:37:52 WARN Failed to register uploaded object key=gqmlcqwm929j1yh6kayww0j56xqdkl1s.narinfo error="server returned 404: 404 page not found\n"15872026/10/09 17:37:52 INFO Completed push id=2 objects=3 duration=4.72019ms15882026/10/09 17:37:52 INFO Upload complete. (68ms)15892026/10/09 17:37:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15902026/10/09 17:37:52 INFO Uploading rz58jvjrplw5b87px2h0zf0jgc77pxq6-test-script (136B)15912026/10/09 17:37:52 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15922026/10/09 17:37:52 INFO Received push request method=POST path=/api/pushes15932026/10/09 17:37:52 WARN Failed to register uploaded object key=rz58jvjrplw5b87px2h0zf0jgc77pxq6.ls error="server returned 404: 404 page not found\n"15942026/10/09 17:37:52 INFO Received complete push request method=POST path=/api/pushes/1/complete15952026/10/09 17:37:52 INFO Received push request method=POST path=/api/pushes15962026/10/09 17:37:52 WARN Failed to register uploaded object key=log/h2jwkrnyylp8yf27wi7lrwrfxrcqn7jy-test-script.drv error="server returned 404: 404 page not found\n"15972026/10/09 17:37:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15982026/10/09 17:37:52 INFO Signed narinfos id=1 count=115992026/10/09 17:37:52 INFO Uploading 1 narinfos16002026/10/09 17:37:52 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16012026/10/09 17:37:52 INFO Uploading a51y62wsvw4zmfjj596052jzbgkhvh3d-test-file.txt (152B)16022026/10/09 17:37:52 INFO Received complete push request method=POST path=/api/pushes/1/complete16032026/10/09 17:37:52 WARN Failed to register uploaded object key=rz58jvjrplw5b87px2h0zf0jgc77pxq6.narinfo error="server returned 404: 404 page not found\n"16042026/10/09 17:37:52 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16052026/10/09 17:37:52 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16062026/10/09 17:37:52 INFO Uploading nm6pwm62dv8s80mraqsp3lxj97s15bxm-test-file-2.txt (160B)16072026/10/09 17:37:52 INFO Uploading 8hqjnki8fhagfifdbrm5m3nc49v7ykbm-test-file-0.txt (160B)16082026/10/09 17:37:52 INFO Uploading 6h0jnf08bp1yzgrxnbm276diagmiy5yh-test-file-1.txt (160B)16092026/10/09 17:37:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16102026/10/09 17:37:52 WARN Failed to register uploaded object key=a51y62wsvw4zmfjj596052jzbgkhvh3d.ls error="server returned 404: 404 page not found\n"16112026/10/09 17:37:52 INFO Completed push id=1 objects=6 duration=9.032102ms16122026/10/09 17:37:52 INFO Signed narinfos id=1 count=116132026/10/09 17:37:52 INFO Uploading 1 narinfos1614--- PASS: TestPush_CompleteCommitsEveryRoot (0.23s)1615=== CONT TestReadProxyConditionalGet16162026/10/09 17:37:52 INFO Completed push id=1 objects=4 duration=6.827407ms16172026/10/09 17:37:52 INFO Upload complete. (68ms)16182026/10/09 17:37:52 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16192026/10/09 17:37:52 WARN Failed to register uploaded object key=6h0jnf08bp1yzgrxnbm276diagmiy5yh.ls error="server returned 404: 404 page not found\n"16202026/10/09 17:37:52 INFO Received complete push request method=POST path=/api/pushes/1/complete16212026/10/09 17:37:52 WARN Failed to register uploaded object key=a51y62wsvw4zmfjj596052jzbgkhvh3d.narinfo error="server returned 404: 404 page not found\n"16222026/10/09 17:37:52 WARN Failed to register uploaded object key=8hqjnki8fhagfifdbrm5m3nc49v7ykbm.ls error="server returned 404: 404 page not found\n"16232026/10/09 17:37:52 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16242026/10/09 17:37:52 WARN Failed to register uploaded object key=nm6pwm62dv8s80mraqsp3lxj97s15bxm.ls error="server returned 404: 404 page not found\n"16252026/10/09 17:37:52 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16262026/10/09 17:37:52 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"1627=== NAME TestClientWithDependencies16282026/10/09 17:37:52 INFO Signed narinfos id=1 count=31629 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies3262926552/001/store) requires matching store prefix16302026/10/09 17:37:52 INFO Uploading 3 narinfos16312026/10/09 17:37:52 WARN Failed to register uploaded object key=6h0jnf08bp1yzgrxnbm276diagmiy5yh.narinfo error="server returned 404: 404 page not found\n"16322026/10/09 17:37:52 WARN Failed to register uploaded object key=nm6pwm62dv8s80mraqsp3lxj97s15bxm.narinfo error="server returned 404: 404 page not found\n"16332026/10/09 17:37:52 INFO Received complete push request method=POST path=/api/pushes/1/complete16342026/10/09 17:37:52 WARN Failed to register uploaded object key=8hqjnki8fhagfifdbrm5m3nc49v7ykbm.narinfo error="server returned 404: 404 page not found\n"16352026/10/09 17:37:52 INFO lead: acquired remote=192.0.2.1:123416362026/10/09 17:37:52 INFO lead: released remote=192.0.2.1:12341637--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.24s)1638=== CONT TestReadProxyInvalidPath1639--- PASS: TestClientWithDependencies (0.52s)1640=== CONT TestCacheStatsHandler16412026/10/09 17:37:52 INFO Starting cleanup of old closures method=DELETE path=/api/closures16422026/10/09 17:37:52 INFO Garbage collection started16432026/10/09 17:37:52 INFO Completed push id=1 objects=3 duration=18.394112ms16442026/10/09 17:37:52 INFO Upload complete. (74ms)16452026/10/09 17:37:52 INFO Completed push id=1 objects=9 duration=13.683223ms16462026/10/09 17:37:52 INFO Upload complete. (75ms)1647=== NAME TestClientMultipleUploads1648 client_integration_test.go:369: Uploaded 3 paths in 110.071146ms16492026/10/09 17:37:52 INFO Received push request method=POST path=/api/pushes1650--- PASS: TestClientMultipleUploads (0.52s)1651=== CONT TestReadProxy40416522026/10/09 17:37:52 INFO Aborted multipart uploads count=0 kept=016532026/10/09 17:37:52 WARN Force mode enabled - objects will be deleted immediately without grace period16542026/10/09 17:37:52 INFO All 1 paths already cached1655=== NAME TestClientIntegration1656 client_integration_test.go:312: Retrieved narinfo from S3:1657 StorePath: /build/TestClientIntegration3210132810/002/store/a51y62wsvw4zmfjj596052jzbgkhvh3d-test-file.txt1658 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1659 Compression: zstd1660 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11661 NarSize: 1521662 References: 1663 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11664 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1665 client_integration_test.go:313: Decompressed .ls content (64 bytes):1666 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1667 client_integration_test.go:316: Testing garbage collection...16682026/10/09 17:37:52 INFO lead: acquired remote=192.0.2.1:123416692026/10/09 17:37:52 INFO lead: acquired remote=192.0.2.1:12341670--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.27s)1671=== CONT TestCacheConfigHandler1672=== RUN TestCacheConfigHandler/full_config,_no_issuer1673=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1674=== RUN TestCacheConfigHandler/no_cache_url_configured1675=== PAUSE TestCacheConfigHandler/no_cache_url_configured1676=== RUN TestCacheConfigHandler/no_signing_keys1677=== PAUSE TestCacheConfigHandler/no_signing_keys1678=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1679=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1680=== CONT TestService_ReadScope_PublicByDefault16812026/10/09 17:37:52 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=016822026/10/09 17:37:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44945/oidc16832026/10/09 17:37:52 INFO lead: acquired remote=192.0.2.1:123416842026/10/09 17:37:52 INFO Vacuumed table table=pending_closures16852026/10/09 17:37:52 INFO lead: released remote=192.0.2.1:123416862026/10/09 17:37:52 INFO Vacuumed table table=pending_objects16872026/10/09 17:37:52 INFO Vacuumed table table=multipart_uploads16882026/10/09 17:37:52 INFO Vacuumed table table=closures16892026/10/09 17:37:52 INFO Vacuumed table table=objects16902026/10/09 17:37:52 INFO Starting cleanup of old closures method=DELETE path=/api/closures16912026/10/09 17:37:52 INFO Garbage collection started16922026/10/09 17:37:52 INFO lead: acquired remote=192.0.2.1:123416932026/10/09 17:37:52 INFO Aborted multipart uploads count=0 kept=016942026/10/09 17:37:52 WARN Force mode enabled - objects will be deleted immediately without grace period16952026/10/09 17:37:52 INFO lead: acquired remote=192.0.2.1:123416962026/10/09 17:37:52 INFO lead: released remote=192.0.2.1:123416972026/10/09 17:37:52 INFO lead: released remote=192.0.2.1:123416982026/10/09 17:37:52 INFO lead: released remote=192.0.2.1:12341699--- PASS: TestLeadScopedToFarm (0.29s)1700=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1701--- PASS: TestReadRedirectUsesPublicS3URL (0.27s)1702=== CONT TestService_RequireScope_OIDC1703--- PASS: TestGCBugBareHashReferences (0.50s)1704=== CONT TestService_ReadAuthMiddleware17052026/10/09 17:37:52 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=017062026/10/09 17:37:52 INFO Vacuumed table table=pending_closures17072026/10/09 17:37:52 INFO Vacuumed table table=pending_objects17082026/10/09 17:37:52 INFO Vacuumed table table=multipart_uploads1709--- PASS: TestReadProxyRangeRequest (0.28s)1710=== CONT TestService_AuthMiddleware17112026/10/09 17:37:52 INFO Vacuumed table table=closures17122026/10/09 17:37:52 INFO Vacuumed table table=objects1713--- PASS: TestReadRedirectNar (0.26s)1714=== CONT TestService_AuthMiddleware_MTLSProxyHeader1715--- PASS: TestReadRedirectKeepsNarinfoProxied (0.28s)1716=== CONT TestReadProxyHead17172026/10/09 17:37:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44925/oidc1718--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.29s)1719=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17202026/10/09 17:37:52 INFO Received uploads request method=POST path=/1721=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17222026/10/09 17:37:52 INFO Received request for more parts method=POST path=/1723=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17242026/10/09 17:37:52 INFO Received complete multipart upload request method=POST path=/1725=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17262026/10/09 17:37:52 INFO Received uploads request method=POST path=/1727--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1728 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1729 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1730 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1731 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1732=== CONT TestFarmLeadRoutes//api/farm/lead1733=== CONT TestFarmLeadRoutes//api/farm/lead/build-x861734--- PASS: TestFarmLeadRoutes (0.07s)1735 --- PASS: TestFarmLeadRoutes//api/farm/lead (0.00s)1736 --- PASS: TestFarmLeadRoutes//api/farm/lead/build-x86 (0.00s)1737=== CONT TestPendingClosureWriteTimeout/empty1738=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1739--- PASS: TestReadProxyConditionalGet (0.26s)1740=== CONT TestPendingClosureWriteTimeout/400_objects1741=== CONT TestPendingClosureWriteTimeout/670k_objects1742=== CONT TestProxyWriteTimeout/narinfo1743=== CONT TestProxyWriteTimeout/10_GiB_nar1744=== CONT TestProxyWriteTimeout/1_GiB_nar1745=== CONT TestProxyWriteTimeout/unknown_size1746--- PASS: TestProxyWriteTimeout (0.06s)1747 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1748 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1749 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1750 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1751=== CONT TestIsValidUploadKey/narinfo1752=== CONT TestIsValidUploadKey/realisation_plus_in_output1753=== CONT TestIsValidUploadKey/unknown_type1754=== CONT TestIsValidUploadKey/empty_key1755=== CONT TestIsValidUploadKey/absolute1756=== CONT TestIsValidUploadKey/traversal_nar1757=== CONT TestIsValidUploadKey/traversal1758=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1759=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1760=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1761=== CONT TestIsValidUploadKey/index.html1762=== CONT TestIsValidUploadKey/nix-cache-info1763=== CONT TestIsValidUploadKey/build_log_equals1764=== CONT TestIsValidUploadKey/realisation1765=== CONT TestIsValidUploadKey/build_log_question_mark1766=== CONT TestIsValidUploadKey/build_log_plus_in_name1767=== CONT TestIsValidUploadKey/nar_plain1768=== CONT TestIsValidUploadKey/build_log1769=== CONT TestIsValidUploadKey/listing1770=== CONT TestIsValidUploadKey/nar_xz1771=== CONT TestIsValidUploadKey/nar_zst1772=== CONT TestIsValidUploadKey/build_log_home-manager_file1773=== CONT TestIsValidCachePath/narinfo1774--- PASS: TestIsValidUploadKey (0.07s)1775 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1776 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1777 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1778 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1779 --- PASS: TestIsValidUploadKey/absolute (0.00s)1780 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1781 --- PASS: TestIsValidUploadKey/traversal (0.00s)1782 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1783 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1784 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1785 --- PASS: TestIsValidUploadKey/index.html (0.00s)1786 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1787 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1788 --- PASS: TestIsValidUploadKey/realisation (0.00s)1789 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1790 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1791 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1792 --- PASS: TestIsValidUploadKey/build_log (0.00s)1793 --- PASS: TestIsValidUploadKey/listing (0.00s)1794 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1795 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1796 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1797=== CONT TestIsValidCachePath/index.html1798=== CONT TestIsValidCachePath/short_hash1799=== CONT TestIsValidCachePath/wrong_extension1800=== CONT TestIsValidCachePath/leading_slash1801=== CONT TestIsValidCachePath/empty1802=== CONT TestIsValidCachePath/random_path1803=== CONT TestIsValidCachePath/invalid_char_u1804=== CONT TestIsValidCachePath/invalid_char_e1805=== CONT TestIsValidCachePath/traversal_in_middle1806=== CONT TestIsValidCachePath/traversal_parent1807=== CONT TestIsValidCachePath/nar_uncompressed1808=== CONT TestIsValidCachePath/nar_xz1809=== CONT TestIsValidCachePath/nix-cache-info1810=== CONT TestIsValidCachePath/nar_bz21811=== CONT TestIsValidCachePath/realisation1812=== CONT TestIsValidCachePath/ls1813=== CONT TestIsValidCachePath/log1814=== CONT TestIsValidCachePath/nar_zst1815=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1816--- PASS: TestIsValidCachePath (0.00s)1817 --- PASS: TestIsValidCachePath/narinfo (0.00s)1818 --- PASS: TestIsValidCachePath/index.html (0.00s)1819 --- PASS: TestIsValidCachePath/short_hash (0.00s)1820 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1821 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1822 --- PASS: TestIsValidCachePath/empty (0.00s)1823 --- PASS: TestIsValidCachePath/random_path (0.00s)1824 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1825 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1826 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1827 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1828 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1829 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1830 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1831 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1832 --- PASS: TestIsValidCachePath/realisation (0.00s)1833 --- PASS: TestIsValidCachePath/ls (0.00s)1834 --- PASS: TestIsValidCachePath/log (0.00s)1835 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1836 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1837=== CONT TestParseSingleRange/none1838=== CONT TestParseSingleRange/open-ended1839=== CONT TestParseSingleRange/start_far_past_EOF1840=== CONT TestParseSingleRange/start_past_EOF1841=== CONT TestParseSingleRange/single_byte1842=== CONT TestParseSingleRange/suffix_exceeds_size1843=== CONT TestParseSingleRange/suffix1844=== CONT TestParseSingleRange/end_clamped_to_size1845=== CONT TestParseSingleRange/malformed_both_empty1846=== CONT TestParseSingleRange/closed1847=== CONT TestParseSingleRange/malformed_end_before_start1848=== CONT TestParseSingleRange/multi-range_ignored1849=== CONT TestParseSingleRange/unknown_unit1850=== CONT TestParseSingleRange/malformed_no_dash1851--- PASS: TestParseSingleRange (0.00s)1852 --- PASS: TestParseSingleRange/none (0.00s)1853 --- PASS: TestParseSingleRange/open-ended (0.00s)1854 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1855 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1856 --- PASS: TestParseSingleRange/single_byte (0.00s)1857 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1858 --- PASS: TestParseSingleRange/suffix (0.00s)1859 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1860 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1861 --- PASS: TestParseSingleRange/closed (0.00s)1862 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1863 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1864 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1865 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1866=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1867--- PASS: TestCacheStatsHandler (0.27s)1868=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1869--- PASS: TestReadProxyInvalidPath (0.28s)1870=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18712026/10/09 17:37:52 INFO Received uploads request method=POST path=/1872--- PASS: TestObjectStatsLargeCommit (1.85s)1873=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18742026/10/09 17:37:52 INFO Received request for more parts method=POST path=/1875--- PASS: TestReadProxy404 (0.29s)1876=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18772026/10/09 17:37:52 INFO Received complete multipart upload request method=POST path=/1878--- PASS: TestService_ReadScope_PublicByDefault (0.26s)1879=== CONT TestPush_RejectsBadRequests/bad_root18802026/10/09 17:37:52 INFO Received push request method=POST path=/api/pushes1881=== CONT TestPush_RejectsBadRequests/no_roots18822026/10/09 17:37:52 INFO Received push request method=POST path=/api/pushes1883=== CONT TestPush_RejectsBadRequests/no_objects18842026/10/09 17:37:52 INFO Received push request method=POST path=/api/pushes1885=== CONT TestPush_RejectsBadRequests/root_not_in_objects18862026/10/09 17:37:52 INFO Received push request method=POST path=/api/pushes1887=== CONT TestServerTLSConfig/no_client_CA1888=== CONT TestServerTLSConfig/missing_CA_file1889--- PASS: TestPush_RejectsBadRequests (0.56s)1890 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1891 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1892 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1893 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1894=== CONT TestServerTLSConfig/not_a_PEM_file1895--- PASS: TestServerTLSConfig (0.00s)1896 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1897 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1898 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1899=== CONT TestGCEndsOnShutdown/before_the_run1900=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1901=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1902=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1903=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1904=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1905=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1906=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1907=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1908=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1909=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19102026/10/09 17:37:52 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19112026/10/09 17:37:52 WARN mTLS auth: bound subjects configured but subject DN unavailable19122026/10/09 17:37:52 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1913--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.24s)1914=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1915=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1916--- PASS: TestService_ReadAuthMiddleware (0.25s)1917=== CONT TestClientErrorHandling/InvalidStorePath19182026/10/09 17:37:52 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1919--- PASS: TestService_AuthMiddleware (0.26s)1920=== CONT TestClientErrorHandling/ServerNotAvailable1921--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.25s)1922=== CONT TestClientErrorHandling/InvalidAuthToken1923--- PASS: TestReadProxyHead (0.26s)1924=== CONT TestResolveDBConnectionString/flag_wins1925=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1926=== CONT TestResolveDBConnectionString/nothing_configured1927=== CONT TestResolveDBConnectionString/missing_file_is_an_error1928=== CONT TestResolveDBConnectionString/file_when_flag_empty1929=== CONT TestCacheConfigHandler/full_config,_no_issuer1930--- PASS: TestResolveDBConnectionString (0.00s)1931 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1932 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1933 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1934 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1935 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1936=== CONT TestCacheConfigHandler/no_signing_keys1937=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1938=== CONT TestCacheConfigHandler/no_cache_url_configured1939--- PASS: TestCacheConfigHandler (0.00s)1940 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1941 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1942 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1943 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1944=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1945=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19462026/10/09 17:37:52 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]1947=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19482026/10/09 17:37:52 WARN Authentication failed token_preview=eyJhbGciOi..._L29u0m4Dw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1949=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1950--- PASS: TestService_AuthMiddleware_OIDC (0.40s)1951 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1952 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1953 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1954 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)19552026/10/09 17:37:52 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1956=== RUN TestService_RequireScope_OIDC/builder_may_write1957=== PAUSE TestService_RequireScope_OIDC/builder_may_write1958=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1959=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1960=== RUN TestService_RequireScope_OIDC/ops_may_admin1961=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1962=== RUN TestService_RequireScope_OIDC/ops_may_not_write1963=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1964=== RUN TestService_RequireScope_OIDC/reader_may_not_write1965=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1966=== RUN TestService_RequireScope_OIDC/static_token_may_admin1967=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1968=== RUN TestService_RequireScope_OIDC/static_token_may_write1969=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1970=== RUN TestService_RequireScope_OIDC/reader_may_read1971=== PAUSE TestService_RequireScope_OIDC/reader_may_read1972=== RUN TestService_RequireScope_OIDC/writer_implies_read1973=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1974=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1975=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1976=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1977=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1978=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1979=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1980=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1981=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1982=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1983=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1984=== CONT TestService_RequireScope_OIDC/builder_may_write1985=== CONT TestService_RequireScope_OIDC/reader_may_read1986=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1987=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19882026/10/09 17:37:52 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]1989=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1990=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1991=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1992=== CONT TestService_RequireScope_OIDC/writer_implies_read1993=== CONT TestService_RequireScope_OIDC/static_token_may_write1994=== CONT TestService_RequireScope_OIDC/reader_may_not_write1995=== CONT TestService_RequireScope_OIDC/static_token_may_admin1996=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1997=== CONT TestService_RequireScope_OIDC/ops_may_admin1998=== CONT TestService_RequireScope_OIDC/ops_may_not_write1999--- PASS: TestService_RequireScope_OIDC (0.36s)2000 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2001 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2002 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2003 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2004 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2005 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2006 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2007 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2008 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2009 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2010 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2011 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2012 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2013 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)20142026/10/09 17:37:52 INFO Received uploads request method=POST path=/api/pending_closures20152026-10-09 17:37:52.674 UTC [133] LOG: checkpoints are occurring too frequently (8 seconds apart)20162026-10-09 17:37:52.674 UTC [133] HINT: Consider increasing the configuration parameter "max_wal_size".20172026-10-09 17:37:52.674 UTC [133] LOG: checkpoint starting: wal20182026/10/09 17:37:52 WARN Request failed, retrying attempt=2 backoff=216.532211ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20192026/10/09 17:37:52 INFO Aborted multipart uploads count=0 kept=020202026/10/09 17:37:52 WARN Force mode enabled - objects will be deleted immediately without grace period20212026/10/09 17:37:52 INFO Aborted multipart uploads count=0 kept=020222026/10/09 17:37:52 WARN Force mode enabled - objects will be deleted immediately without grace period20232026-10-09 17:37:52.799 UTC [2071] ERROR: canceling statement due to user request20242026-10-09 17:37:52.799 UTC [2071] CONTEXT: SQL statement "UPDATE object_stats s2025 SET object_count = s.object_count + n.n - o.n,2026 total_bytes = s.total_bytes + n.bytes - o.bytes2027 FROM (2028 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes2029 FROM new_rows WHERE deleted_at IS NULL2030 ) AS n,2031 (2032 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes2033 FROM old_rows WHERE deleted_at IS NULL2034 ) AS o2035 WHERE s.id AND (n.n <> o.n OR n.bytes <> o.bytes)"2036 PL/pgSQL function object_stats_update() line 3 at SQL statement20372026-10-09 17:37:52.799 UTC [2071] STATEMENT: -- name: MarkStaleObjects :execrows2038 WITH RECURSIVE ct AS (2039 SELECT timezone('UTC', now()) AS now2040 ),2041 closure_reach AS (2042 -- Start with all closure keys2043 SELECT o.key, o.refs2044 FROM objects o2045 INNER JOIN closures c ON o.key = c.key2046 UNION2047 -- Recursively add all referenced objects2048 SELECT o.key, o.refs2049 FROM objects o2050 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2051 ),2052 reachable_objects AS (2053 SELECT DISTINCT key FROM closure_reach2054 ),2055 stale_objects AS (2056 SELECT o.key2057 FROM objects AS o, ct2058 WHERE2059 NOT EXISTS (2060 SELECT 12061 FROM reachable_objects ro2062 WHERE ro.key = o.key2063 )2064 AND NOT EXISTS (2065 SELECT 12066 FROM pending_objects AS po2067 WHERE po.key = o.key2068 )2069 AND o.deleted_at IS NULL -- Only mark fresh objects2070 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2071 FOR UPDATE2072 )2073 UPDATE objects2074 SET2075 deleted_at = ct.now,2076 first_deleted_at = COALESCE(first_deleted_at, ct.now)2077 FROM stale_objects, ct2078 WHERE objects.key = stale_objects.key2079 20802026/10/09 17:37:52 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:43445/bucket97/?delete=\": context canceled"20812026/10/09 17:37:52 INFO Received uploads request method=POST path=/api/pending_closures2082--- PASS: TestGCEndsOnShutdown (0.00s)2083 --- PASS: TestGCEndsOnShutdown/before_the_run (0.26s)2084 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.30s)2085 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.31s)20862026/10/09 17:37:52 INFO Aborted multipart uploads count=0 kept=020872026/10/09 17:37:52 WARN Force mode enabled - objects will be deleted immediately without grace period20882026/10/09 17:37:52 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=020892026/10/09 17:37:52 INFO Vacuumed table table=pending_closures20902026/10/09 17:37:52 INFO Vacuumed table table=pending_objects20912026/10/09 17:37:52 INFO Vacuumed table table=multipart_uploads20922026/10/09 17:37:52 INFO Vacuumed table table=closures20932026/10/09 17:37:52 INFO Vacuumed table table=objects2094=== NAME TestOrphanedObjectsGCStressTest2095 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2096--- PASS: TestDeleteClosuresRacingPins (1.63s)20972026/10/09 17:37:52 INFO Received uploads request method=POST path=/api/pending_closures20982026/10/09 17:37:52 INFO Aborted multipart uploads count=0 kept=02099=== NAME TestOrphanedObjectsGCStressTest2100 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion21012026/10/09 17:37:52 WARN Force mode enabled - objects will be deleted immediately without grace period21022026/10/09 17:37:52 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021032026/10/09 17:37:52 INFO Vacuumed table table=pending_closures21042026/10/09 17:37:52 INFO Vacuumed table table=pending_objects21052026/10/09 17:37:52 INFO Vacuumed table table=multipart_uploads21062026/10/09 17:37:52 INFO Vacuumed table table=closures21072026/10/09 17:37:52 INFO Vacuumed table table=objects2108--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2109 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.31s)2110 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.34s)21112026/10/09 17:37:52 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21122026/10/09 17:37:52 WARN Request failed, retrying attempt=3 backoff=413.601106ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21132026/10/09 17:37:52 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2114--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)2115 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2116 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.05s)2117 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.68s)21182026/10/09 17:37:53 INFO lead: released remote=192.0.2.1:12342119--- PASS: TestLeadEndsOnShutdown (1.29s)2120=== NAME TestOrphanedObjectsGCStressTest2121 orphaned_objects_gc_test.go:503: Stress test completed successfully:2122 orphaned_objects_gc_test.go:504: - Active objects preserved: 202123 orphaned_objects_gc_test.go:505: - Objects deleted: 2102124 orphaned_objects_gc_test.go:506: - Total GC'd: 2102125--- PASS: TestOrphanedObjectsGCStressTest (2.59s)2126--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2127 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.78s)2128 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.77s)21292026/10/09 17:37:53 WARN Request failed, retrying attempt=4 backoff=830.852563ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21302026/10/09 17:37:53 INFO lead: released remote=192.0.2.1:12342131--- PASS: TestPendingClosureWriteTimeout (0.06s)2132 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2133 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2134 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2135 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.08s)21362026/10/09 17:37:53 INFO lead: acquired remote=192.0.2.1:123421372026/10/09 17:37:54 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021382026/10/09 17:37:54 INFO Received create pin request method=POST path=/api/pins/myapp21392026/10/09 17:37:54 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC2837679242/001/store/8hg57ah1h080y9m36sghqdhcxlah6ys6-pinned-file.txt narinfo_key=8hg57ah1h080y9m36sghqdhcxlah6ys6.narinfo21402026/10/09 17:37:54 INFO Starting cleanup of old closures method=DELETE path=/api/closures21412026/10/09 17:37:54 INFO Garbage collection started21422026/10/09 17:37:54 INFO Aborted multipart uploads count=0 kept=021432026/10/09 17:37:54 WARN Request failed, retrying attempt=5 backoff=1.495816434s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21442026/10/09 17:37:54 WARN Force mode enabled - objects will be deleted immediately without grace period21452026/10/09 17:37:54 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=021462026/10/09 17:37:54 INFO Vacuumed table table=pending_closures21472026/10/09 17:37:54 INFO Vacuumed table table=pending_objects21482026/10/09 17:37:54 INFO Vacuumed table table=multipart_uploads21492026/10/09 17:37:54 INFO Vacuumed table table=closures21502026/10/09 17:37:54 INFO Vacuumed table table=objects21512026/10/09 17:37:54 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02152=== NAME TestClientIntegration2153 client_integration_test.go:323: Objects in database after GC:2154 client_integration_test.go:323: Successfully deleted all objects with GC --force2155--- PASS: TestClientIntegration (2.47s)21562026/10/09 17:37:54 INFO lead: released remote=192.0.2.1:12342157--- PASS: TestLeadElectsOneAndHandsOver (2.60s)21582026/10/09 17:37:55 WARN Rate limiter enabled after throttle name=s3-test rate=521592026/10/09 17:37:55 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2160=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2161 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102162 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002163--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.35s)21642026/10/09 17:37:55 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21652026/10/09 17:37:55 WARN Request failed, retrying attempt=2 backoff=209.249763ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21662026/10/09 17:37:56 WARN Request failed, retrying attempt=3 backoff=421.701423ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2167=== NAME TestPinProtectsFromGC2168 client_integration_test.go:840: Pin successfully protected closure from garbage collection2169--- PASS: TestPinProtectsFromGC (4.73s)21702026/10/09 17:37:56 WARN Request failed, retrying attempt=4 backoff=781.617449ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2171--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.49s)21722026/10/09 17:37:57 WARN Request failed, retrying attempt=5 backoff=1.613652347s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2173--- PASS: TestConnectWaitsForAPeerMigration (5.21s)21742026/10/09 17:37:57 INFO Aborted multipart uploads count=1 kept=021752026/10/09 17:37:57 INFO Received cleanup request method=DELETE path=/api/pending_closures21762026/10/09 17:37:57 INFO Aborted multipart uploads count=1 kept=02177--- PASS: TestPendingCleanupUsesOneCutoff (6.70s)21782026/10/09 17:37:58 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"21792026/10/09 17:37:58 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21802026/10/09 17:37:58 WARN Request failed, retrying attempt=2 backoff=192.563481ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21812026/10/09 17:37:59 WARN Request failed, retrying attempt=3 backoff=407.34976ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21822026/10/09 17:37:59 WARN Request failed, retrying attempt=4 backoff=860.208047ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21832026/10/09 17:38:00 WARN Request failed, retrying attempt=5 backoff=1.488061715s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21842026/10/09 17:38:01 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21852026/10/09 17:38:02 WARN Request failed, retrying attempt=2 backoff=185.177825ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21862026/10/09 17:38:02 WARN Request failed, retrying attempt=3 backoff=415.679955ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21872026/10/09 17:38:02 WARN Request failed, retrying attempt=4 backoff=879.158598ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21882026/10/09 17:38:03 WARN Request failed, retrying attempt=5 backoff=1.475865077s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2189--- PASS: TestClientErrorHandling (0.00s)2190 --- PASS: TestClientErrorHandling/InvalidStorePath (0.31s)2191 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.55s)2192 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.44s)2193PASS2194{"timestamp":"2026-10-09T17:38:05.004224262Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:39088","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(391)"}21952026-10-09 17:38:05.438 UTC [128] LOG: received smart shutdown request21962026-10-09 17:38:05.443 UTC [128] LOG: background worker "logical replication launcher" (PID 138) exited with exit code 121972026-10-09 17:38:06.924 UTC [133] LOG: checkpoint complete: wrote 10735 buffers (65.5%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=13.037 s, sync=1.148 s, total=14.251 s; sync files=34381, longest=0.017 s, average=0.001 s; distance=533644 kB, estimate=533644 kB; lsn=0/226292B0, redo lsn=0/22088FA021982026-10-09 17:38:06.927 UTC [133] LOG: shutting down21992026-10-09 17:38:06.927 UTC [133] LOG: checkpoint starting: shutdown immediate22002026-10-09 17:38:06.971 UTC [133] LOG: checkpoint complete: wrote 241 buffers (1.5%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.007 s, sync=0.033 s, total=0.044 s; sync files=158, longest=0.001 s, average=0.001 s; distance=5760 kB, estimate=480856 kB; lsn=0/22629328, redo lsn=0/2262932822012026-10-09 17:38:07.054 UTC [128] LOG: database system is shut down2202Running OIDC tests...2203=== RUN TestAudienceForIssuer2204=== PAUSE TestAudienceForIssuer2205=== RUN TestGlobMatch2206=== PAUSE TestGlobMatch2207=== RUN TestValidateToken_ValidToken2208=== PAUSE TestValidateToken_ValidToken2209=== RUN TestValidateToken_WrongAudience2210=== PAUSE TestValidateToken_WrongAudience2211=== RUN TestValidateToken_Expired2212=== PAUSE TestValidateToken_Expired2213=== RUN TestValidateToken_BoundClaimsMismatch2214=== PAUSE TestValidateToken_BoundClaimsMismatch2215=== RUN TestValidateToken_BoundSubjectMismatch2216=== PAUSE TestValidateToken_BoundSubjectMismatch2217=== RUN TestValidateToken_MultipleProviders2218=== PAUSE TestValidateToken_MultipleProviders2219=== RUN TestValidateToken_NoMatchingProvider2220=== PAUSE TestValidateToken_NoMatchingProvider2221=== RUN TestValidateToken_KubernetesServiceAccount2222=== PAUSE TestValidateToken_KubernetesServiceAccount2223=== RUN TestNewValidator_KubernetesRequiresCA2224=== PAUSE TestNewValidator_KubernetesRequiresCA2225=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2226=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2227=== RUN TestPins_ReservedForMatchingRule2228=== PAUSE TestPins_ReservedForMatchingRule2229=== RUN TestPins_TopLevelShorthand2230=== PAUSE TestPins_TopLevelShorthand2231=== RUN TestPins_ConfigValidation2232=== PAUSE TestPins_ConfigValidation2233=== RUN TestScopes_LegacyProviderDefaultsToWrite2234=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2235=== RUN TestScopes_Rules2236=== PAUSE TestScopes_Rules2237=== RUN TestScopes_ConfigValidation2238=== PAUSE TestScopes_ConfigValidation2239=== CONT TestAudienceForIssuer2240=== CONT TestScopes_ConfigValidation2241--- PASS: TestAudienceForIssuer (0.00s)2242=== CONT TestValidateToken_KubernetesServiceAccount2243=== CONT TestValidateToken_Expired2244=== CONT TestValidateToken_WrongAudience2245=== CONT TestValidateToken_ValidToken2246--- PASS: TestScopes_ConfigValidation (0.00s)2247=== CONT TestGlobMatch2248=== RUN TestGlobMatch/foo_foo2249=== PAUSE TestGlobMatch/foo_foo2250=== RUN TestGlobMatch/foo_bar2251=== PAUSE TestGlobMatch/foo_bar2252=== RUN TestGlobMatch/*_2253=== PAUSE TestGlobMatch/*_2254=== CONT TestValidateToken_NoMatchingProvider2255=== CONT TestPins_TopLevelShorthand2256=== CONT TestScopes_Rules2257=== CONT TestScopes_LegacyProviderDefaultsToWrite2258=== CONT TestPins_ConfigValidation2259=== CONT TestValidateToken_BoundSubjectMismatch2260=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2261=== CONT TestPins_ReservedForMatchingRule2262=== CONT TestNewValidator_KubernetesRequiresCA2263=== CONT TestValidateToken_BoundClaimsMismatch2264=== CONT TestValidateToken_MultipleProviders2265=== RUN TestGlobMatch/*_anything2266=== PAUSE TestGlobMatch/*_anything2267=== RUN TestGlobMatch/foo*_foo2268=== PAUSE TestGlobMatch/foo*_foo2269--- PASS: TestPins_ConfigValidation (0.00s)2270=== RUN TestGlobMatch/foo*_foobar2271=== PAUSE TestGlobMatch/foo*_foobar2272=== RUN TestGlobMatch/foo*_bar2273=== PAUSE TestGlobMatch/foo*_bar2274=== RUN TestGlobMatch/*bar_bar2275=== PAUSE TestGlobMatch/*bar_bar2276=== RUN TestGlobMatch/*bar_foobar2277=== PAUSE TestGlobMatch/*bar_foobar2278=== RUN TestGlobMatch/*bar_foo2279=== PAUSE TestGlobMatch/*bar_foo2280=== RUN TestGlobMatch/foo*bar_foobar2281=== PAUSE TestGlobMatch/foo*bar_foobar2282=== RUN TestGlobMatch/foo*bar_foo123bar2283=== PAUSE TestGlobMatch/foo*bar_foo123bar2284=== RUN TestGlobMatch/foo*bar_foobarbaz2285=== PAUSE TestGlobMatch/foo*bar_foobarbaz2286=== RUN TestGlobMatch/*/*_foo/bar2287=== PAUSE TestGlobMatch/*/*_foo/bar2288=== RUN TestGlobMatch/*/*_foo2289=== PAUSE TestGlobMatch/*/*_foo2290=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2291=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2292=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02293=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02294=== RUN TestGlobMatch/refs/*/main_refs/heads/main2295=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2296=== RUN TestGlobMatch/fo?_foo2297=== PAUSE TestGlobMatch/fo?_foo2298=== RUN TestGlobMatch/fo?_fo2299=== PAUSE TestGlobMatch/fo?_fo2300=== RUN TestGlobMatch/fo?_fooo2301=== PAUSE TestGlobMatch/fo?_fooo2302=== RUN TestGlobMatch/?oo_foo2303=== PAUSE TestGlobMatch/?oo_foo2304=== RUN TestGlobMatch/?oo_boo2305=== PAUSE TestGlobMatch/?oo_boo2306=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2307=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2308=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2309=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2310=== CONT TestGlobMatch/foo_foo2311=== CONT TestGlobMatch/?oo_boo2312=== CONT TestGlobMatch/?oo_foo2313=== CONT TestGlobMatch/fo?_fooo2314=== CONT TestGlobMatch/fo?_fo2315=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2316=== CONT TestGlobMatch/foo_bar2317=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2318=== CONT TestGlobMatch/foo*bar_foobar2319=== CONT TestGlobMatch/refs/*/main_refs/heads/main2320=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02321=== CONT TestGlobMatch/*bar_foo2322=== CONT TestGlobMatch/*/*_foo2323=== CONT TestGlobMatch/foo*bar_foobarbaz2324=== CONT TestGlobMatch/*bar_foobar2325=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2326=== CONT TestGlobMatch/*bar_bar2327=== CONT TestGlobMatch/foo*_bar2328=== CONT TestGlobMatch/foo*_foobar2329=== CONT TestGlobMatch/foo*_foo2330=== CONT TestGlobMatch/*_anything2331=== CONT TestGlobMatch/*_2332=== CONT TestGlobMatch/fo?_foo2333=== CONT TestGlobMatch/*/*_foo/bar2334=== CONT TestGlobMatch/foo*bar_foo123bar2335--- PASS: TestGlobMatch (0.01s)2336 --- PASS: TestGlobMatch/foo_foo (0.00s)2337 --- PASS: TestGlobMatch/?oo_boo (0.00s)2338 --- PASS: TestGlobMatch/?oo_foo (0.00s)2339 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2340 --- PASS: TestGlobMatch/fo?_fo (0.00s)2341 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2342 --- PASS: TestGlobMatch/foo_bar (0.00s)2343 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2344 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2345 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2346 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2347 --- PASS: TestGlobMatch/*bar_foo (0.00s)2348 --- PASS: TestGlobMatch/*/*_foo (0.00s)2349 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2350 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2351 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2352 --- PASS: TestGlobMatch/*bar_bar (0.00s)2353 --- PASS: TestGlobMatch/foo*_bar (0.00s)2354 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2355 --- PASS: TestGlobMatch/foo*_foo (0.00s)2356 --- PASS: TestGlobMatch/*_anything (0.00s)2357 --- PASS: TestGlobMatch/fo?_foo (0.00s)2358 --- PASS: TestGlobMatch/*_ (0.00s)2359 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2360 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)23612026/10/09 17:38:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40925/oidc2362--- PASS: TestValidateToken_Expired (0.03s)23632026/10/09 17:38:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37061/oidc23642026/10/09 17:38:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44763/oidc23652026/10/09 17:38:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40083/oidc2366--- PASS: TestValidateToken_WrongAudience (0.04s)2367--- PASS: TestPins_TopLevelShorthand (0.04s)23682026/10/09 17:38:09 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:435092369--- PASS: TestPins_ReservedForMatchingRule (0.04s)23702026/10/09 17:38:09 http: TLS handshake error from 127.0.0.1:55258: remote error: tls: bad certificate2371--- PASS: TestNewValidator_KubernetesRequiresCA (0.04s)2372--- PASS: TestValidateToken_KubernetesServiceAccount (0.05s)23732026/10/09 17:38:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44349/oidc2374--- PASS: TestValidateToken_BoundClaimsMismatch (0.05s)23752026/10/09 17:38:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32999/oidc2376--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.06s)23772026/10/09 17:38:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38939/oidc2378--- PASS: TestValidateToken_ValidToken (0.06s)23792026/10/09 17:38:09 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34379/oidc2380--- PASS: TestScopes_Rules (0.07s)23812026/10/09 17:38:10 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43493/oidc2382--- PASS: TestValidateToken_BoundSubjectMismatch (0.10s)23832026/10/09 17:38:10 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323842026/10/09 17:38:10 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:43961/oidc2385--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.11s)2386--- PASS: TestValidateToken_NoMatchingProvider (0.11s)23872026/10/09 17:38:10 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:45159/oidc23882026/10/09 17:38:10 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:42335/oidc2389--- PASS: TestValidateToken_MultipleProviders (0.18s)2390PASS2391Running hook tests...2392=== RUN TestSendPathsEmpty2393=== PAUSE TestSendPathsEmpty2394=== RUN TestQueueEnqueueAndFetch2395=== PAUSE TestQueueEnqueueAndFetch2396=== RUN TestQueueDeduplication2397=== PAUSE TestQueueDeduplication2398=== RUN TestQueueRemove2399=== PAUSE TestQueueRemove2400=== RUN TestQueueFetchBatchLimit2401=== PAUSE TestQueueFetchBatchLimit2402=== RUN TestQueueRetryMovesToBack2403=== PAUSE TestQueueRetryMovesToBack2404=== RUN TestQueueFetchRemoveLifecycle2405=== PAUSE TestQueueFetchRemoveLifecycle2406=== RUN TestQueueConcurrentWriters2407=== PAUSE TestQueueConcurrentWriters2408=== RUN TestQueueRemoveLargeClosure2409=== PAUSE TestQueueRemoveLargeClosure2410=== RUN TestServerClientIntegration2411--- PASS: TestServerClientIntegration (0.00s)2412=== RUN TestServerQueueError24132026/10/09 17:38:10 ERROR Failed to queue paths error="permission denied" count=12414--- PASS: TestServerQueueError (0.00s)2415=== RUN TestGetListenerSocketActivation2416 server_test.go:219: === RUN TestGetListenerSocketActivation2417 --- PASS: TestGetListenerSocketActivation (0.00s)2418 PASS2419 2420--- PASS: TestGetListenerSocketActivation (0.01s)2421=== RUN TestDrainIsolatesPoisonPath2422=== PAUSE TestDrainIsolatesPoisonPath2423=== RUN TestRunNotBlockedByPoisonHead2424=== PAUSE TestRunNotBlockedByPoisonHead2425=== RUN TestDrainGivesUpWhenServerDown2426=== PAUSE TestDrainGivesUpWhenServerDown2427=== RUN TestFailedPathPrunedByLaterClosure2428=== PAUSE TestFailedPathPrunedByLaterClosure2429=== RUN TestWorkerUploadsAndRemoves2430=== PAUSE TestWorkerUploadsAndRemoves2431=== RUN TestWorkerSkipsGCdPaths2432=== PAUSE TestWorkerSkipsGCdPaths2433=== RUN TestWorkerPrunesClosureDeps2434=== PAUSE TestWorkerPrunesClosureDeps2435=== RUN TestDrainTimeout2436=== PAUSE TestDrainTimeout2437=== CONT TestSendPathsEmpty2438=== CONT TestWorkerPrunesClosureDeps2439--- PASS: TestSendPathsEmpty (0.00s)2440=== CONT TestDrainTimeout2441=== CONT TestDrainIsolatesPoisonPath2442=== CONT TestQueueRemoveLargeClosure2443=== CONT TestQueueConcurrentWriters2444=== CONT TestQueueFetchRemoveLifecycle2445=== CONT TestFailedPathPrunedByLaterClosure2446=== CONT TestQueueRetryMovesToBack2447=== CONT TestWorkerSkipsGCdPaths2448=== CONT TestQueueFetchBatchLimit2449=== CONT TestQueueRemove2450=== CONT TestWorkerUploadsAndRemoves2451=== CONT TestQueueEnqueueAndFetch2452=== CONT TestDrainGivesUpWhenServerDown2453=== CONT TestRunNotBlockedByPoisonHead2454=== CONT TestQueueDeduplication24552026/10/09 17:38:10 INFO Upload queue status pending=224562026/10/09 17:38:10 INFO Upload queue status pending=324572026/10/09 17:38:10 INFO Uploading batch count=124582026/10/09 17:38:10 ERROR Upload failed error="upload failed" count=124592026/10/09 17:38:10 INFO Uploading batch count=224602026/10/09 17:38:10 INFO Uploading batch count=224612026/10/09 17:38:10 INFO Uploading batch count=12462--- PASS: TestQueueFetchBatchLimit (0.02s)24632026/10/09 17:38:10 ERROR Upload failed error="upload failed" count=124642026/10/09 17:38:10 INFO Uploading batch count=424652026/10/09 17:38:10 ERROR Upload failed error="upload failed" count=424662026/10/09 17:38:10 INFO Uploading batch count=124672026/10/09 17:38:10 INFO Upload queue status pending=224682026/10/09 17:38:10 INFO Upload queue status pending=224692026/10/09 17:38:10 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1470974452/002/nonexistent24702026/10/09 17:38:10 INFO Uploading batch count=12471--- PASS: TestQueueEnqueueAndFetch (0.02s)24722026/10/09 17:38:10 INFO Uploading batch count=224732026/10/09 17:38:10 ERROR Upload failed error="upload failed" count=22474--- PASS: TestQueueRemove (0.02s)24752026/10/09 17:38:10 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1188720508/002/a24762026/10/09 17:38:10 INFO Uploading batch count=124772026/10/09 17:38:10 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1821015908/002/bbb2478--- PASS: TestQueueFetchRemoveLifecycle (0.02s)2479--- PASS: TestQueueRetryMovesToBack (0.02s)24802026/10/09 17:38:10 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1188720508/002/b24812026/10/09 17:38:10 INFO Uploading batch count=12482--- PASS: TestQueueDeduplication (0.02s)24832026/10/09 17:38:10 INFO Uploading batch count=224842026/10/09 17:38:10 ERROR Upload failed error="upload failed" count=224852026/10/09 17:38:10 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1188720508/002/c24862026/10/09 17:38:10 INFO Uploading batch count=124872026/10/09 17:38:10 ERROR Upload failed error="upload failed" count=124882026/10/09 17:38:10 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1188720508/002/d24892026/10/09 17:38:10 INFO Uploading batch count=12490--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24912026/10/09 17:38:10 ERROR Upload failed error="upload failed" count=124922026/10/09 17:38:10 INFO Uploading batch count=224932026/10/09 17:38:10 ERROR Upload failed error="upload failed" count=224942026/10/09 17:38:10 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1188720508/002/e24952026/10/09 17:38:10 INFO Uploading batch count=124962026/10/09 17:38:10 ERROR Upload failed error="upload failed" count=124972026/10/09 17:38:10 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1188720508/002/f24982026/10/09 17:38:10 ERROR Drain finished with paths left in queue remaining=124992026/10/09 17:38:10 ERROR Drain finished with paths left in queue remaining=102500--- PASS: TestDrainIsolatesPoisonPath (0.03s)2501--- PASS: TestDrainGivesUpWhenServerDown (0.03s)2502--- PASS: TestWorkerUploadsAndRemoves (0.04s)2503--- PASS: TestWorkerPrunesClosureDeps (0.04s)2504--- PASS: TestWorkerSkipsGCdPaths (0.04s)2505--- PASS: TestQueueRemoveLargeClosure (0.05s)25062026/10/09 17:38:10 ERROR Upload failed error="context deadline exceeded" count=225072026/10/09 17:38:10 ERROR Drain finished with paths left in queue remaining=42508--- PASS: TestDrainTimeout (0.22s)2509--- PASS: TestQueueConcurrentWriters (0.28s)25102026/10/09 17:38:11 INFO Uploading batch count=125112026/10/09 17:38:11 INFO Uploading batch count=125122026/10/09 17:38:11 INFO Uploading batch count=125132026/10/09 17:38:11 ERROR Upload failed error="upload failed" count=125142026/10/09 17:38:11 INFO Uploading batch count=125152026/10/09 17:38:11 ERROR Upload failed error="upload failed" count=125162026/10/09 17:38:11 INFO Uploading batch count=125172026/10/09 17:38:11 ERROR Upload failed error="upload failed" count=125182026/10/09 17:38:11 INFO Uploading batch count=125192026/10/09 17:38:11 ERROR Upload failed error="upload failed" count=125202026/10/09 17:38:11 ERROR Drain finished with paths left in queue remaining=12521--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2522PASS2523Running signing tests...2524=== RUN TestExternalSigner2525=== PAUSE TestExternalSigner2526=== RUN TestExternalSignerWrongPublicKey2527=== PAUSE TestExternalSignerWrongPublicKey2528=== RUN TestExternalSignerErrors2529=== PAUSE TestExternalSignerErrors2530=== RUN TestExternalSignerRestartsAfterCrash2531=== PAUSE TestExternalSignerRestartsAfterCrash2532=== RUN TestExternalSignerProgramErrorKeepsProcess2533=== PAUSE TestExternalSignerProgramErrorKeepsProcess2534=== RUN TestExternalSignerClose2535=== PAUSE TestExternalSignerClose2536=== RUN TestExternalSignerRejectsInvalidPublicKey2537=== PAUSE TestExternalSignerRejectsInvalidPublicKey2538=== RUN TestExternalSignerCancellation2539=== PAUSE TestExternalSignerCancellation2540=== RUN TestGenerateFingerprint2541=== PAUSE TestGenerateFingerprint2542=== RUN TestParseSigningKey2543=== PAUSE TestParseSigningKey2544=== RUN TestSign2545=== PAUSE TestSign2546=== RUN TestSignBatch2547=== PAUSE TestSignBatch2548=== RUN TestNilKeyPublicKey2549=== PAUSE TestNilKeyPublicKey2550=== RUN TestSignErrors2551=== PAUSE TestSignErrors2552=== CONT TestExternalSigner2553=== CONT TestExternalSignerCancellation2554=== CONT TestSign2555=== CONT TestExternalSignerProgramErrorKeepsProcess2556=== CONT TestParseSigningKey2557=== CONT TestExternalSignerRejectsInvalidPublicKey2558=== RUN TestExternalSignerRejectsInvalidPublicKey/#002559=== CONT TestExternalSignerClose2560=== CONT TestGenerateFingerprint2561=== RUN TestGenerateFingerprint/basic_with_references2562=== PAUSE TestGenerateFingerprint/basic_with_references2563=== CONT TestExternalSignerErrors2564=== CONT TestExternalSignerRestartsAfterCrash2565=== CONT TestExternalSignerWrongPublicKey2566=== CONT TestSignErrors2567=== CONT TestNilKeyPublicKey2568=== CONT TestSignBatch2569=== RUN TestParseSigningKey/valid_32-byte_key2570=== PAUSE TestParseSigningKey/valid_32-byte_key2571=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2572=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2573=== RUN TestExternalSignerErrors/wrong_id2574=== PAUSE TestExternalSignerErrors/wrong_id2575=== RUN TestExternalSignerErrors/null_signatures2576=== PAUSE TestExternalSignerErrors/null_signatures2577=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002578=== RUN TestParseSigningKey/no_colon2579=== PAUSE TestParseSigningKey/no_colon2580=== RUN TestSignErrors/nil_key2581=== PAUSE TestSignErrors/nil_key2582--- PASS: TestSign (0.00s)2583=== RUN TestGenerateFingerprint/no_references2584=== RUN TestExternalSignerErrors/unrequested_key2585=== PAUSE TestExternalSignerErrors/unrequested_key2586=== RUN TestExternalSignerErrors/program_error2587=== PAUSE TestExternalSignerErrors/program_error2588=== RUN TestSignErrors/nil_narinfo2589=== RUN TestParseSigningKey/empty_name2590=== PAUSE TestParseSigningKey/empty_name2591=== PAUSE TestSignErrors/nil_narinfo2592=== RUN TestExternalSignerErrors/exit_on_request2593=== PAUSE TestExternalSignerErrors/exit_on_request2594=== RUN TestExternalSignerErrors/wrong_signatures_shape2595=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2596=== RUN TestExternalSignerErrors/missing_signature_name2597=== PAUSE TestExternalSignerErrors/missing_signature_name2598=== RUN TestExternalSignerErrors/wrong_signature_length2599=== PAUSE TestExternalSignerErrors/wrong_signature_length2600=== RUN TestExternalSignerErrors/exit_at_startup2601=== PAUSE TestExternalSignerErrors/exit_at_startup2602=== RUN TestExternalSignerErrors/invalid_JSON2603=== PAUSE TestExternalSignerErrors/invalid_JSON2604=== RUN TestExternalSignerErrors/null2605=== PAUSE TestExternalSignerErrors/null2606=== RUN TestExternalSignerErrors/wrong_signature_name2607=== PAUSE TestExternalSignerErrors/wrong_signature_name2608=== RUN TestExternalSignerErrors/wrong_shape2609=== PAUSE TestExternalSignerErrors/wrong_shape2610=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2611=== PAUSE TestGenerateFingerprint/no_references2612--- PASS: TestNilKeyPublicKey (0.00s)2613--- PASS: TestSignBatch (0.00s)2614=== RUN TestParseSigningKey/invalid_base642615=== PAUSE TestParseSigningKey/invalid_base642616=== RUN TestSignErrors/invalid_narinfo2617=== PAUSE TestSignErrors/invalid_narinfo2618=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2619=== RUN TestExternalSignerErrors/missing_signatures2620=== PAUSE TestExternalSignerErrors/missing_signatures2621=== RUN TestExternalSignerErrors/too_few_signatures2622=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2623=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2624=== RUN TestParseSigningKey/wrong_length2625=== PAUSE TestParseSigningKey/wrong_length2626=== CONT TestParseSigningKey/valid_32-byte_key2627=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2628=== RUN TestSignErrors/canceled2629=== CONT TestParseSigningKey/no_colon2630=== CONT TestParseSigningKey/invalid_base642631=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2632=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2633--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2634=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2635=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2636=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2637=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2638=== CONT TestExternalSignerRejectsInvalidPublicKey/#002639=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2640=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2641=== RUN TestGenerateFingerprint/invalid_nar_hash_length2642=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2643=== CONT TestParseSigningKey/wrong_length2644=== CONT TestParseSigningKey/empty_name2645=== PAUSE TestSignErrors/canceled2646=== CONT TestSignErrors/nil_key2647=== PAUSE TestExternalSignerErrors/too_few_signatures2648--- PASS: TestExternalSignerClose (0.00s)2649=== RUN TestExternalSignerErrors/invalid_signature_base642650=== PAUSE TestExternalSignerErrors/invalid_signature_base642651=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2652=== CONT TestExternalSignerErrors/invalid_JSON2653=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2654=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2655=== CONT TestExternalSignerErrors/exit_at_startup2656=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2657=== RUN TestGenerateFingerprint/invalid_store_path_prefix2658=== CONT TestSignErrors/invalid_narinfo2659=== CONT TestSignErrors/canceled2660=== CONT TestSignErrors/nil_narinfo2661--- PASS: TestParseSigningKey (0.00s)2662 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2663 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2664 --- PASS: TestParseSigningKey/no_colon (0.00s)2665 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2666 --- PASS: TestParseSigningKey/wrong_length (0.00s)2667 --- PASS: TestParseSigningKey/empty_name (0.00s)2668=== CONT TestExternalSignerErrors/wrong_id2669=== CONT TestExternalSignerErrors/invalid_signature_base642670=== CONT TestExternalSignerErrors/too_few_signatures2671=== CONT TestExternalSignerErrors/missing_signatures2672=== CONT TestExternalSignerErrors/wrong_shape2673=== CONT TestExternalSignerErrors/wrong_signatures_shape2674=== CONT TestExternalSignerErrors/exit_on_request2675=== CONT TestExternalSignerErrors/missing_signature_name2676=== CONT TestExternalSignerErrors/program_error2677=== CONT TestExternalSignerErrors/wrong_signature_name2678=== CONT TestExternalSignerErrors/unrequested_key2679=== CONT TestExternalSignerErrors/null2680=== CONT TestExternalSignerErrors/null_signatures2681=== CONT TestExternalSignerErrors/wrong_signature_length2682=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2683--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2684 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2685 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2686 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2687 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2688 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2689--- PASS: TestExternalSignerWrongPublicKey (0.00s)2690=== RUN TestGenerateFingerprint/invalid_reference_prefix2691--- PASS: TestExternalSigner (0.01s)2692--- PASS: TestSignErrors (0.00s)2693 --- PASS: TestSignErrors/nil_key (0.00s)2694 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2695 --- PASS: TestSignErrors/canceled (0.00s)2696 --- PASS: TestSignErrors/nil_narinfo (0.00s)2697=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2698=== CONT TestGenerateFingerprint/basic_with_references2699=== CONT TestGenerateFingerprint/invalid_nar_hash_length2700=== CONT TestGenerateFingerprint/no_references2701=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2702=== CONT TestGenerateFingerprint/invalid_reference_prefix2703=== CONT TestGenerateFingerprint/invalid_store_path_prefix2704=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2705--- PASS: TestGenerateFingerprint (0.01s)2706 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2707 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2708 --- PASS: TestGenerateFingerprint/no_references (0.00s)2709 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2710 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2711 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2712 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2713--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2714--- PASS: TestExternalSignerErrors (0.00s)2715 --- PASS: TestExternalSignerErrors/invalid_JSON (0.00s)2716 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2717 --- PASS: TestExternalSignerErrors/wrong_shape (0.00s)2718 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2719 --- PASS: TestExternalSignerErrors/unrequested_key (0.00s)2720 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)2721 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2722 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2723 --- PASS: TestExternalSignerErrors/program_error (0.01s)2724 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)2725 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2726 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2727 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2728 --- PASS: TestExternalSignerErrors/null (0.01s)2729 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2730 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2731--- PASS: TestExternalSignerCancellation (0.02s)2732PASS2733Running OpenBao signer tests...2734=== RUN TestSign2735=== PAUSE TestSign2736=== RUN TestSignErrors2737=== PAUSE TestSignErrors2738=== RUN TestServe2739=== PAUSE TestServe2740=== RUN TestServeRejectsGarbage2741=== PAUSE TestServeRejectsGarbage2742=== CONT TestSign2743=== CONT TestServe2744=== CONT TestServeRejectsGarbage2745=== CONT TestSignErrors2746--- PASS: TestServeRejectsGarbage (0.00s)2747=== RUN TestSignErrors/http_error2748=== PAUSE TestSignErrors/http_error2749=== RUN TestSignErrors/invalid_json2750=== PAUSE TestSignErrors/invalid_json2751=== RUN TestSignErrors/no_prefix2752=== PAUSE TestSignErrors/no_prefix2753=== RUN TestSignErrors/invalid_base642754--- PASS: TestServe (0.00s)2755=== PAUSE TestSignErrors/invalid_base642756=== CONT TestSignErrors/http_error2757=== CONT TestSignErrors/invalid_json2758=== CONT TestSignErrors/no_prefix2759=== CONT TestSignErrors/invalid_base642760--- PASS: TestSign (0.00s)2761--- PASS: TestSignErrors (0.00s)2762 --- PASS: TestSignErrors/invalid_json (0.00s)2763 --- PASS: TestSignErrors/http_error (0.00s)2764 --- PASS: TestSignErrors/invalid_base64 (0.00s)2765 --- PASS: TestSignErrors/no_prefix (0.00s)2766PASS

succeeded niks3-go-unit-tests checks.x86_64-linux.go-unit-tests · build #403 · raw

succeeded `niks3-go-unit-tests` `checks.x86_64-linux.go-unit-tests` · build #403 · raw