niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #403
· raw
1tribuchet: building on eliza2Running 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 TestScriptTokenEmptyCommand106--- PASS: TestScriptTokenEmptyCommand (0.00s)107=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica108=== CONT TestDoServerRequestAttachesToken109=== CONT TestDoWithRetry_BodyReplayedViaGetBody110=== CONT TestResolveStorePath111=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess112=== CONT TestRateLimiterFeedback113=== RUN TestRateLimiterFeedback/429_enables_limiter114=== PAUSE TestRateLimiterFeedback/429_enables_limiter115=== CONT TestPathInfoCACompatibility116=== RUN TestPathInfoCACompatibility/null_ca_field117=== CONT TestParsePathInfoJSONMultiplePaths118=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths119=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths120=== CONT TestParsePathInfoJSON121=== RUN TestParsePathInfoJSON/Nix_format122=== PAUSE TestParsePathInfoJSON/Nix_format123=== CONT TestPathInfoHashCompatibility124=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)125=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)126=== CONT TestGetStorePathHash127=== CONT TestConvertHashToNix32128=== CONT TestEncodeNixBase32WithRealHash129=== CONT TestEncodeNixBase32130=== CONT TestDumpPathWriterError131=== CONT TestDumpPathSingleFile132=== CONT TestDumpPathMatchesNix133=== CONT TestUploadMultipart_SupersededByPeer134=== CONT TestPartSizeForNAR135=== CONT TestUploadMultipart_PartsInParallel136=== CONT TestFilterOversizedClosures137=== CONT TestCaseHackSuffix138=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun139=== CONT TestRetryTimeoutOutlastsMaxRetries140=== RUN TestRateLimiterFeedback/503_enables_limiter141=== RUN TestGetStorePathHash/valid_store_path142--- PASS: TestResolveStorePath (0.00s)143=== RUN TestPartSizeForNAR/zero_stays_at_minimum144=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum145=== RUN TestPartSizeForNAR/small_stays_at_minimum146=== PAUSE TestPartSizeForNAR/small_stays_at_minimum147=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum148=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum149=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts150=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts151=== RUN TestPartSizeForNAR/1_TiB152=== PAUSE TestPartSizeForNAR/1_TiB153=== RUN TestPartSizeForNAR/5_TiB_S3_max_object154=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object155=== RUN TestPartSizeForNAR/capped_at_5_GiB156=== PAUSE TestPartSizeForNAR/capped_at_5_GiB157=== RUN TestEncodeNixBase32/test_string_hash158=== PAUSE TestPathInfoCACompatibility/null_ca_field159--- PASS: TestEncodeNixBase32WithRealHash (0.00s)160=== PAUSE TestGetStorePathHash/valid_store_path161=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths162=== RUN TestParsePathInfoJSON/Lix_format163=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon164=== RUN TestConvertHashToNix32/SRI_format_to_Nix32165=== CONT TestRegisterUploadedObjectReusesConnections166=== CONT TestSetClientTLS167=== RUN TestFilterOversizedClosures/no_limit_keeps_everything168=== PAUSE TestRateLimiterFeedback/503_enables_limiter169=== RUN TestUploadMultipart_SupersededByPeer/exists170=== CONT TestScriptTokenScriptFails1712026/10/09 17:37:43 WARN Rate limiter enabled after throttle name=server-test rate=5172=== RUN TestGetStorePathHash/basename_without_hyphen_should_error173=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error174=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error175=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error176=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error177=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error178=== RUN TestPathInfoCACompatibility/old_string_format_-_text179=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text180=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive181=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive182=== RUN TestPathInfoCACompatibility/new_structured_format_-_text183=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text184=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method185=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method1862026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:333951872026/10/09 17:37:44 WARN Rate limiter enabled after throttle name=server-test rate=51882026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:39761189=== CONT TestScriptTokenBadJSON190=== CONT TestScriptTokenEmptyToken191=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter1922026/10/09 17:37:44 INFO Garbage collection started1932026/10/09 17:37:44 WARN Rate limiter backed off name=server-test rate=51942026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:39761195=== PAUSE TestEncodeNixBase32/test_string_hash196=== RUN TestEncodeNixBase32/empty_input197--- PASS: TestCaseHackSuffix (0.19s)198--- PASS: TestScriptTokenScriptFails (0.03s)199=== CONT TestScriptTokenCachesUntilRefresh2002026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:33395201=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter202=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter203=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter204=== PAUSE TestUploadMultipart_SupersededByPeer/exists205=== RUN TestUploadMultipart_SupersededByPeer/missing206=== CONT TestFileTokenEmpty207--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.30s)208=== CONT TestFileTokenMissing209=== RUN TestSetClientTLS/rejects_connection_without_client_cert210=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert211=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA212--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.31s)213=== CONT TestFileTokenReadsAndCaches214=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon215=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI2162026/10/09 17:37:44 INFO Garbage collection started217=== PAUSE TestParsePathInfoJSON/Lix_format218=== RUN TestParsePathInfoJSON/empty_input219=== PAUSE TestParsePathInfoJSON/empty_input220=== RUN TestParsePathInfoJSON/whitespace_only221=== PAUSE TestParsePathInfoJSON/whitespace_only222=== RUN TestParsePathInfoJSON/invalid_JSON223=== PAUSE TestParsePathInfoJSON/invalid_JSON224=== CONT TestScriptTokenNoExpiryRerunsEveryCall225=== CONT TestSetClientTLSDoesNotMutateDefaultTransport226=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix322272026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:33395228=== RUN TestConvertHashToNix32/already_Nix32_format2292026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:33395230=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths231--- PASS: TestFileTokenEmpty (0.01s)232=== CONT TestStreamPushGivesUpOnDeadServer233--- PASS: TestScriptTokenEmptyToken (0.12s)234=== CONT TestStreamPushStopsWhenCanceled2352026/10/09 17:37:44 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=0236=== CONT TestStaticToken237--- PASS: TestStaticToken (0.00s)238=== CONT TestClientSignaturesByStorePath239=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything240=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped241=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped242=== RUN TestFilterOversizedClosures/all_closures_skipped243=== PAUSE TestFilterOversizedClosures/all_closures_skipped2442026/10/09 17:37:44 WARN Garbage collection finished on another replica. Its statistics are not available here245=== CONT TestStreamPushReportsSkippedPaths246--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.32s)247=== CONT TestStreamPushReportsSignatures2482026/10/09 17:37:44 ERROR Upload failed error="connection refused" count=202492026/10/09 17:37:44 ERROR Server seems unavailable, giving up on batch untried=17250--- PASS: TestScriptTokenCachesUntilRefresh (0.03s)251=== CONT TestStreamPushRequestLine252--- PASS: TestScriptTokenBadJSON (0.02s)253=== CONT TestStreamPushReportsEveryPath2542026/10/09 17:37:44 ERROR Upload failed error=boom count=1255--- PASS: TestStreamPushReportsSignatures (0.02s)256=== CONT TestStreamPushIsolatesFailures2572026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:33395258--- PASS: TestStreamPushGivesUpOnDeadServer (0.02s)259=== CONT TestStreamPushBatchesUnderLoad2602026/10/09 17:37:44 ERROR Upload failed error="bad path" count=3261--- PASS: TestStreamPushIsolatesFailures (0.00s)262=== CONT TestShellSplitErrors263--- PASS: TestShellSplitErrors (0.00s)264=== CONT TestSetClientTLSErrors2652026/10/09 17:37:44 ERROR Upload failed error=boom count=1266--- PASS: TestStreamPushReportsSkippedPaths (0.02s)267=== CONT TestShellSplit268--- PASS: TestShellSplit (0.00s)269=== CONT TestPartSizeForNAR/zero_stays_at_minimum270=== CONT TestPartSizeForNAR/capped_at_5_GiB271=== CONT TestPartSizeForNAR/5_TiB_S3_max_object272=== CONT TestPartSizeForNAR/1_TiB273=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts274=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum275=== CONT TestPartSizeForNAR/small_stays_at_minimum276--- PASS: TestPartSizeForNAR (0.00s)277 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)278 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)279 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)280 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)281 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)282 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)283 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)284=== CONT TestGetStorePathHash/valid_store_path285=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error286=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error287=== CONT TestGetStorePathHash/basename_without_hyphen_should_error288--- PASS: TestGetStorePathHash (0.16s)289 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)290 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)291 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)292 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)293=== CONT TestPathInfoCACompatibility/null_ca_field294=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method295=== CONT TestPathInfoCACompatibility/new_structured_format_-_text296=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive297=== CONT TestPathInfoCACompatibility/old_string_format_-_text298--- PASS: TestPathInfoCACompatibility (0.16s)299 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)300 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)301 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)302 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)303 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)304=== RUN TestSetClientTLSErrors/missing_cert_file305=== PAUSE TestSetClientTLSErrors/missing_cert_file306=== RUN TestSetClientTLSErrors/missing_key_file307=== PAUSE TestSetClientTLSErrors/missing_key_file308=== RUN TestSetClientTLSErrors/missing_ca_file309=== PAUSE TestSetClientTLSErrors/missing_ca_file310=== RUN TestSetClientTLSErrors/invalid_ca_file311=== PAUSE TestSetClientTLSErrors/invalid_ca_file312=== CONT TestRateLimiterFeedback/429_enables_limiter313=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter314--- PASS: TestDumpPathSingleFile (0.34s)315=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter316=== PAUSE TestEncodeNixBase32/empty_input317=== PAUSE TestUploadMultipart_SupersededByPeer/missing318=== CONT TestParsePathInfoJSON/Nix_format319--- PASS: TestDoServerRequestAttachesToken (0.34s)320=== CONT TestParsePathInfoJSON/whitespace_only3212026/10/09 17:37:44 WARN Rate limiter enabled after throttle name=server-test rate=5322=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA3232026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:39917324=== RUN TestSetClientTLS/preserves_debug_logging_transport325=== PAUSE TestSetClientTLS/preserves_debug_logging_transport326=== CONT TestParsePathInfoJSON/invalid_JSON327=== CONT TestParsePathInfoJSON/empty_input328--- PASS: TestFileTokenMissing (0.01s)329=== CONT TestRateLimiterFeedback/503_enables_limiter330=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths331=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI332=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512333=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512334--- PASS: TestFileTokenReadsAndCaches (0.00s)335=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3362026/10/09 17:37:44 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=2000337=== CONT TestFilterOversizedClosures/all_closures_skipped3382026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:33395339=== CONT TestParsePathInfoJSON/Lix_format3402026/10/09 17:37:44 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=503412026/10/09 17:37:44 WARN Rate limiter backed off name=server-test rate=5342=== CONT TestSetClientTLSErrors/invalid_ca_file343=== CONT TestSetClientTLSErrors/missing_ca_file344=== CONT TestEncodeNixBase32/test_string_hash345=== CONT TestUploadMultipart_SupersededByPeer/exists346=== CONT TestUploadMultipart_SupersededByPeer/missing347=== CONT TestSetClientTLS/rejects_connection_without_client_cert3482026/10/09 17:37:44 WARN Rate limiter enabled after throttle name=server-test rate=53492026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:38265350=== CONT TestSetClientTLSErrors/missing_cert_file351=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths352=== CONT TestSetClientTLS/preserves_debug_logging_transport3532026/10/09 17:37:44 WARN Rate limiter backed off name=server-test rate=53542026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:33395355=== CONT TestEncodeNixBase32/empty_input356--- PASS: TestEncodeNixBase32 (0.34s)357 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)358 --- PASS: TestEncodeNixBase32/empty_input (0.00s)359=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA360=== CONT TestFilterOversizedClosures/no_limit_keeps_everything361--- PASS: TestFilterOversizedClosures (0.31s)362 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)363 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)364 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)365=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512366=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon367=== CONT TestSetClientTLSErrors/missing_key_file368--- PASS: TestSetClientTLSErrors (0.01s)369 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)370 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)371 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)372 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)373=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)374=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI375--- PASS: TestPathInfoHashCompatibility (0.35s)376 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)377 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)378 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)379 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)3802026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:33395381=== PAUSE TestConvertHashToNix32/already_Nix32_format382=== RUN TestConvertHashToNix32/invalid_format383=== PAUSE TestConvertHashToNix32/invalid_format384=== CONT TestConvertHashToNix32/SRI_format_to_Nix32385--- PASS: TestStreamPushStopsWhenCanceled (0.00s)386=== CONT TestConvertHashToNix32/invalid_format387=== CONT TestConvertHashToNix32/already_Nix32_format388--- PASS: TestConvertHashToNix32 (0.35s)389 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)390 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)391 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)392--- PASS: TestClientSignaturesByStorePath (0.00s)393--- PASS: TestParsePathInfoJSONMultiplePaths (0.31s)394 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)395 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)396--- PASS: TestParsePathInfoJSON (0.31s)397 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)398 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)399 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)400 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)401 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)402--- PASS: TestStreamPushReportsEveryPath (0.00s)403--- PASS: TestRateLimiterFeedback (0.31s)404 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)405 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)406 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)407 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)408--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)4092026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:33395410--- PASS: TestUploadMultipart_SupersededByPeer (0.22s)411 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)412 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)4132026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:333954142026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:333954152026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:333954162026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:333954172026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:333954182026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:333954192026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:33395420--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.02s)4212026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:33395422--- PASS: TestRegisterUploadedObjectReusesConnections (0.21s)4232026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:333954242026/10/09 17:37:44 http: TLS handshake error from 127.0.0.1:46024: remote error: tls: bad certificate425--- PASS: TestSetClientTLS (0.35s)426 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)427 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)428 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4292026/10/09 17:37:44 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:33395430--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.37s)431--- PASS: TestDumpPathWriterError (0.22s)432--- PASS: TestStreamPushRequestLine (0.05s)433--- PASS: TestDumpPathMatchesNix (0.41s)434--- PASS: TestStreamPushBatchesUnderLoad (0.11s)435--- PASS: TestUploadMultipart_PartsInParallel (0.96s)436--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.16s)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/postgres4289953441/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/postgres4289953441/data -l logfile start465466/build/postgres4289953441:5432 - no response467/build/postgres4289953441:5432 - no response4682026-10-09 17:37:46.798 UTC [132] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit469/build/postgres4289953441:5432 - no response4702026-10-09 17:37:46.799 UTC [132] LOG: listening on Unix socket "/build/postgres4289953441/.s.PGSQL.5432"4712026-10-09 17:37:46.803 UTC [141] LOG: database system was shut down at 2026-10-09 17:37:46 UTC4722026-10-09 17:37:46.808 UTC [132] LOG: database system is ready to accept connections473/build/postgres4289953441:5432 - accepting connections474{"timestamp":"2026-10-09T17:37:47.739150659Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"b75902aa-312c-4345-8681-4d5969de267a","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(198)"}475=== RUN TestFarmLeadRoutes476=== PAUSE TestFarmLeadRoutes477=== RUN TestService_AuthMiddleware478=== PAUSE TestService_AuthMiddleware479=== RUN TestService_AuthMiddleware_MTLSProxyHeader480=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader481=== RUN TestService_AuthMiddleware_MTLSBoundSubjects482=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects483=== RUN TestService_ReadAuthMiddleware484=== PAUSE TestService_ReadAuthMiddleware485=== RUN TestService_AuthMiddleware_OIDC486=== PAUSE TestService_AuthMiddleware_OIDC487=== RUN TestService_RequireScope_OIDC488=== PAUSE TestService_RequireScope_OIDC489=== RUN TestService_ReadScope_PublicByDefault490=== PAUSE TestService_ReadScope_PublicByDefault491=== RUN TestCacheConfigHandler492=== PAUSE TestCacheConfigHandler493=== RUN TestCacheStatsHandler494=== PAUSE TestCacheStatsHandler495=== RUN TestClientCADerivations496=== PAUSE TestClientCADerivations497=== RUN TestClientErrorHandling498=== PAUSE TestClientErrorHandling499=== RUN TestClientIntegration500=== PAUSE TestClientIntegration501=== RUN TestClientMultipleUploads502=== PAUSE TestClientMultipleUploads503=== RUN TestClientWithDependencies504=== PAUSE TestClientWithDependencies505=== RUN TestClientSharedPathCommittedMidPush506=== PAUSE TestClientSharedPathCommittedMidPush507=== RUN TestPinProtectsFromGC508=== PAUSE TestPinProtectsFromGC509=== RUN TestClientPushesUseOnePush510=== PAUSE TestClientPushesUseOnePush511=== RUN TestClientFallsBackToClosures512=== PAUSE TestClientFallsBackToClosures513=== RUN TestDeleteClosuresRacingPins514=== PAUSE TestDeleteClosuresRacingPins515=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock516=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock517=== RUN TestResolveDBConnectionString518=== PAUSE TestResolveDBConnectionString519=== RUN TestConnectWaitsForAPeerMigration520=== PAUSE TestConnectWaitsForAPeerMigration521=== RUN TestLeadElectsOneAndHandsOver522=== PAUSE TestLeadElectsOneAndHandsOver523=== RUN TestLeadScopedToFarm524=== PAUSE TestLeadScopedToFarm525=== RUN TestLeadIncumbentWinsAfterRestart5262026/10/09 17:37:48 INFO lead: acquired remote=192.0.2.1:12345272026/10/09 17:37:48 INFO lead: released remote=192.0.2.1:12345282026/10/09 17:37:48 INFO lead: acquired remote=192.0.2.1:12345292026/10/09 17:37:49 INFO lead: released remote=192.0.2.1:1234530--- PASS: TestLeadIncumbentWinsAfterRestart (2.07s)531=== RUN TestLeadIncumbentAnnouncesAtOnce532=== PAUSE TestLeadIncumbentAnnouncesAtOnce533=== RUN TestLeadEndsOnShutdown534=== PAUSE TestLeadEndsOnShutdown535=== RUN TestLeadEndsWhenItsConnectionHangs5362026/10/09 17:37:50 INFO lead: acquired remote=192.0.2.1:12345372026-10-09 17:37:51.490 UTC [389] FATAL: terminating connection due to administrator command5382026/10/09 17:37:51 INFO lead: acquired remote=192.0.2.1:12345392026/10/09 17:37:52 WARN lead: lock connection lost error="timeout: context deadline exceeded"5402026/10/09 17:37:52 INFO lead: released remote=192.0.2.1:12345412026/10/09 17:37:53 INFO lead: released remote=192.0.2.1:1234542--- PASS: TestLeadEndsWhenItsConnectionHangs (3.17s)543=== RUN TestGCAdvisoryLockBlocksConcurrentRun544=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun545=== RUN TestGCBugBareHashReferences546=== PAUSE TestGCBugBareHashReferences547=== RUN TestGCMetrics548=== PAUSE TestGCMetrics549=== RUN TestPushDedupSurvivesConcurrentGC550=== PAUSE TestPushDedupSurvivesConcurrentGC551=== RUN TestDeduplicatedObjectsRecordedAsPending552=== PAUSE TestDeduplicatedObjectsRecordedAsPending553=== RUN TestGCSweepSkipsPendingObjects554=== PAUSE TestGCSweepSkipsPendingObjects555=== RUN TestTombstonedObjectOfferedWithoutWaiting556=== PAUSE TestTombstonedObjectOfferedWithoutWaiting557=== RUN TestGCSweepDeliversEachKeyOnce558=== PAUSE TestGCSweepDeliversEachKeyOnce559=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection560=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection561=== RUN TestForceGCDuringPushOffersSweptObject562=== PAUSE TestForceGCDuringPushOffersSweptObject563=== RUN TestFailedS3DeleteKeepsTombstone564=== PAUSE TestFailedS3DeleteKeepsTombstone565=== RUN TestSweepSkipsRowsLockedByPush566=== PAUSE TestSweepSkipsRowsLockedByPush567=== RUN TestRegisterCompletedObjectNeedsPendingRow568=== PAUSE TestRegisterCompletedObjectNeedsPendingRow569=== RUN TestGetExistingObjectsLocksRows570=== PAUSE TestGetExistingObjectsLocksRows571=== RUN TestSweepRechecksPendingAfterLocking572=== PAUSE TestSweepRechecksPendingAfterLocking573=== RUN TestPushWaitsForSweepHoldingRow574=== PAUSE TestPushWaitsForSweepHoldingRow575=== RUN TestCommitRacingPendingCleanupKeepsObjects576=== PAUSE TestCommitRacingPendingCleanupKeepsObjects577=== RUN TestGCEndsOnShutdown578=== PAUSE TestGCEndsOnShutdown579=== RUN TestGCTaskStore_StartNew580=== PAUSE TestGCTaskStore_StartNew581=== RUN TestGCTaskStore_DeduplicateSameParams582=== PAUSE TestGCTaskStore_DeduplicateSameParams583=== RUN TestGCTaskStore_ConflictDifferentParams584=== PAUSE TestGCTaskStore_ConflictDifferentParams585=== RUN TestGCTaskStore_GetEmpty586=== PAUSE TestGCTaskStore_GetEmpty587=== RUN TestGCTaskStore_GetReturnsLatest588=== PAUSE TestGCTaskStore_GetReturnsLatest589=== RUN TestGCTaskStore_CompletedAllowsNewTask590=== PAUSE TestGCTaskStore_CompletedAllowsNewTask591=== RUN TestGCTaskStore_PhaseUpdates592=== PAUSE TestGCTaskStore_PhaseUpdates593=== RUN TestGCTaskStore_Fail594=== PAUSE TestGCTaskStore_Fail595=== RUN TestGracefulShutdownDrainsInflight596=== PAUSE TestGracefulShutdownDrainsInflight597=== RUN TestService_healthCheckHandler598=== PAUSE TestService_healthCheckHandler599=== RUN TestService_readinessHandler600=== PAUSE TestService_readinessHandler601=== RUN TestGenerateLandingPage602=== PAUSE TestGenerateLandingPage603=== RUN TestCacheConfigHandlerMaxNarSize604=== PAUSE TestCacheConfigHandlerMaxNarSize605=== RUN TestCreatePendingClosureRejectsOversizedNAR606=== PAUSE TestCreatePendingClosureRejectsOversizedNAR607=== RUN TestNARDeduplicationMetadataUploadBug608=== PAUSE TestNARDeduplicationMetadataUploadBug609=== RUN TestMetricsInventory610=== PAUSE TestMetricsInventory611=== RUN TestMetricsCommit612=== PAUSE TestMetricsCommit613=== RUN TestService_NativeMTLS614=== PAUSE TestService_NativeMTLS615=== RUN TestServerTLSConfig616=== PAUSE TestServerTLSConfig617=== RUN TestMultipartCleanup618=== PAUSE TestMultipartCleanup619=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded620=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded621=== RUN TestPendingCleanupUsesOneCutoff622=== PAUSE TestPendingCleanupUsesOneCutoff623=== RUN TestObjectStatsTrigger624=== PAUSE TestObjectStatsTrigger625=== RUN TestObjectStatsLargeCommit626=== PAUSE TestObjectStatsLargeCommit627=== RUN TestOrphanedObjectsGC628=== PAUSE TestOrphanedObjectsGC629=== RUN TestOrphanedObjectsGCStressTest630=== PAUSE TestOrphanedObjectsGCStressTest631=== RUN TestCreatePin_ReservedPins632=== PAUSE TestCreatePin_ReservedPins633=== RUN TestPresentReportsOnlyClosureRoots634=== PAUSE TestPresentReportsOnlyClosureRoots635=== RUN TestPresentRefreshesOnlyStaleClosures636=== PAUSE TestPresentRefreshesOnlyStaleClosures637=== RUN TestPresentNotReportedWhileGCDeletesClosure638=== PAUSE TestPresentNotReportedWhileGCDeletesClosure639=== RUN TestParseSingleRange640=== PAUSE TestParseSingleRange641=== RUN TestProxyHeadersOnlyTrustedOnSocket6422026/10/09 17:37:53 INFO Starting HTTP server address=127.0.0.1:456556432026/10/09 17:37:53 INFO Starting HTTP server address=proxy.sock6442026/10/09 17:37:53 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6452026/10/09 17:37:53 INFO Shutdown signal received, draining in-flight requests timeout=10s646--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.15s)647=== RUN TestIsValidCachePath648=== PAUSE TestIsValidCachePath649=== RUN TestReadProxyNarinfo650=== PAUSE TestReadProxyNarinfo651=== RUN TestReadProxyNarinfoAlreadyDecompressed652=== PAUSE TestReadProxyNarinfoAlreadyDecompressed653=== RUN TestReadProxyContentNegotiation654=== PAUSE TestReadProxyContentNegotiation655=== RUN TestReadProxyNarStreaming656=== PAUSE TestReadProxyNarStreaming657=== RUN TestReadProxy404658=== PAUSE TestReadProxy404659=== RUN TestReadProxyInvalidPath660=== PAUSE TestReadProxyInvalidPath661=== RUN TestReadProxyHead662=== PAUSE TestReadProxyHead663=== RUN TestReadProxyOutlastsServerWriteTimeout664=== PAUSE TestReadProxyOutlastsServerWriteTimeout665=== RUN TestReadProxyConditionalGet666=== PAUSE TestReadProxyConditionalGet667=== RUN TestReadProxyRootRedirectsToIndexHTML668=== PAUSE TestReadProxyRootRedirectsToIndexHTML669=== RUN TestReadProxyDisabled670=== PAUSE TestReadProxyDisabled671=== RUN TestReadRedirectNar672=== PAUSE TestReadRedirectNar673=== RUN TestReadRedirectKeepsNarinfoProxied674=== PAUSE TestReadRedirectKeepsNarinfoProxied675=== RUN TestReadProxyRangeRequest676=== PAUSE TestReadProxyRangeRequest677=== RUN TestReadRedirectUsesPublicS3URL678=== PAUSE TestReadRedirectUsesPublicS3URL679=== RUN TestPush_OverlappingRootsStoreOneRowPerKey680=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey681=== RUN TestPush_CompleteCommitsEveryRoot682=== PAUSE TestPush_CompleteCommitsEveryRoot683=== RUN TestPush_RepeatedRootCommitsOnce684=== PAUSE TestPush_RepeatedRootCommitsOnce685=== RUN TestPush_CompleteWaitsForCleanupOfThePush686=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush687=== RUN TestPush_RootsAreLockedInByteOrder688=== PAUSE TestPush_RootsAreLockedInByteOrder689=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit690=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit691=== RUN TestPush_RejectsBadRequests692=== PAUSE TestPush_RejectsBadRequests693=== RUN TestPush_SignsNarinfosOfItsPendingObjects694=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects695=== RUN TestRedundantMultipartUpload696=== PAUSE TestRedundantMultipartUpload697=== RUN TestCompleteMultipartUpload_ErrorButObjectExists698=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists699=== RUN TestCompletedNarNotReofferedAcrossClosures700=== PAUSE TestCompletedNarNotReofferedAcrossClosures701=== RUN TestPresignedUploadRegisteredBeforeCommit702=== PAUSE TestPresignedUploadRegisteredBeforeCommit703=== RUN TestService_Rustfstest704=== PAUSE TestService_Rustfstest705=== RUN TestParseSize706=== PAUSE TestParseSize707=== RUN TestSkippedUploadsHandler708=== PAUSE TestSkippedUploadsHandler709=== RUN TestSystemdListenerNotActivated710--- PASS: TestSystemdListenerNotActivated (0.00s)711=== RUN TestWatchdogBeatsWhenHealthy712--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)713=== RUN TestWatchdogSkipsWhenUnhealthy7142026/10/09 17:37:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7152026/10/09 17:37:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7162026/10/09 17:37:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7172026/10/09 17:37:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7182026/10/09 17:37:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7192026/10/09 17:37:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7202026/10/09 17:37:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7212026/10/09 17:37:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7222026/10/09 17:37:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7232026/10/09 17:37:53 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"724--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)725=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle726=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle727=== RUN TestProxyWriteTimeout728=== PAUSE TestProxyWriteTimeout729=== RUN TestPendingClosureWriteTimeout730=== PAUSE TestPendingClosureWriteTimeout731=== RUN TestIsValidUploadKey732=== PAUSE TestIsValidUploadKey733=== RUN TestUploadHandlersRejectInvalidKeys734=== PAUSE TestUploadHandlersRejectInvalidKeys735=== RUN TestUploadHandlersRejectOversizedBody736=== PAUSE TestUploadHandlersRejectOversizedBody737=== RUN TestService_cleanupPendingClosuresHandler738=== PAUSE TestService_cleanupPendingClosuresHandler739=== RUN TestService_createPendingClosureHandler740=== PAUSE TestService_createPendingClosureHandler741=== RUN TestService_verifyS3Integrity742=== PAUSE TestService_verifyS3Integrity743=== RUN TestCompleteMultipartUnregistered744=== PAUSE TestCompleteMultipartUnregistered745=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT746=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT747=== CONT TestProxyWriteTimeout748=== CONT TestPush_SignsNarinfosOfItsPendingObjects749=== CONT TestService_cleanupPendingClosuresHandler750=== RUN TestProxyWriteTimeout/narinfo751=== PAUSE TestProxyWriteTimeout/narinfo752=== RUN TestProxyWriteTimeout/1_GiB_nar753=== PAUSE TestProxyWriteTimeout/1_GiB_nar754=== RUN TestProxyWriteTimeout/10_GiB_nar755=== PAUSE TestProxyWriteTimeout/10_GiB_nar756=== RUN TestProxyWriteTimeout/unknown_size757=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle758=== CONT TestSkippedUploadsHandler759=== CONT TestParseSize760--- PASS: TestParseSize (0.00s)761=== CONT TestService_Rustfstest7622026/10/09 17:37:53 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000763=== CONT TestPresignedUploadRegisteredBeforeCommit764=== CONT TestCompletedNarNotReofferedAcrossClosures765=== CONT TestCompleteMultipartUpload_ErrorButObjectExists766=== CONT TestRedundantMultipartUpload767=== CONT TestFarmLeadRoutes768--- PASS: TestSkippedUploadsHandler (0.01s)769=== CONT TestReadProxyRangeRequest770=== CONT TestIsValidUploadKey771=== CONT TestPendingClosureWriteTimeout772=== CONT TestGCTaskStore_CompletedAllowsNewTask773=== CONT TestPush_RejectsBadRequests774=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit775=== CONT TestPush_RootsAreLockedInByteOrder776=== CONT TestPush_CompleteWaitsForCleanupOfThePush777=== RUN TestIsValidUploadKey/narinfo778=== PAUSE TestIsValidUploadKey/narinfo779=== RUN TestIsValidUploadKey/nar_zst780=== PAUSE TestIsValidUploadKey/nar_zst781=== RUN TestIsValidUploadKey/nar_xz782=== PAUSE TestIsValidUploadKey/nar_xz783=== RUN TestIsValidUploadKey/nar_plain784=== RUN TestPendingClosureWriteTimeout/empty785--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)786=== CONT TestReadRedirectKeepsNarinfoProxied787=== CONT TestPush_RepeatedRootCommitsOnce788=== CONT TestUploadHandlersRejectInvalidKeys789=== CONT TestPush_CompleteCommitsEveryRoot790=== CONT TestPush_OverlappingRootsStoreOneRowPerKey791=== CONT TestUploadHandlersRejectOversizedBody792=== PAUSE TestProxyWriteTimeout/unknown_size793=== CONT TestReadRedirectUsesPublicS3URL794=== RUN TestFarmLeadRoutes//api/farm/lead795=== PAUSE TestFarmLeadRoutes//api/farm/lead796=== RUN TestFarmLeadRoutes//api/farm/lead/build-x86797=== PAUSE TestFarmLeadRoutes//api/farm/lead/build-x86798=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT799=== PAUSE TestIsValidUploadKey/nar_plain800=== PAUSE TestPendingClosureWriteTimeout/empty801=== RUN TestPendingClosureWriteTimeout/400_objects802=== PAUSE TestPendingClosureWriteTimeout/400_objects803=== RUN TestPendingClosureWriteTimeout/670k_objects804=== PAUSE TestPendingClosureWriteTimeout/670k_objects805=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline806=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline807=== RUN TestIsValidUploadKey/listing808=== PAUSE TestIsValidUploadKey/listing809=== RUN TestIsValidUploadKey/build_log810=== PAUSE TestIsValidUploadKey/build_log811=== RUN TestIsValidUploadKey/build_log_home-manager_file812=== PAUSE TestIsValidUploadKey/build_log_home-manager_file813=== RUN TestIsValidUploadKey/build_log_plus_in_name814=== PAUSE TestIsValidUploadKey/build_log_plus_in_name815=== CONT TestReadRedirectNar816=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info817=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info818=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal819=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal820=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key821=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key822=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key823=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key824=== CONT TestCompleteMultipartUnregistered825=== CONT TestReadProxyDisabled826=== RUN TestIsValidUploadKey/build_log_question_mark827=== PAUSE TestIsValidUploadKey/build_log_question_mark828=== RUN TestIsValidUploadKey/build_log_equals829=== PAUSE TestIsValidUploadKey/build_log_equals830=== RUN TestIsValidUploadKey/realisation831=== PAUSE TestIsValidUploadKey/realisation832=== RUN TestIsValidUploadKey/realisation_plus_in_output833=== PAUSE TestIsValidUploadKey/realisation_plus_in_output834=== RUN TestIsValidUploadKey/nix-cache-info835=== PAUSE TestIsValidUploadKey/nix-cache-info836=== RUN TestIsValidUploadKey/index.html837=== PAUSE TestIsValidUploadKey/index.html838=== RUN TestIsValidUploadKey/narinfo_key,_nar_type839=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type840=== RUN TestIsValidUploadKey/nar_key,_narinfo_type841=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type842=== RUN TestIsValidUploadKey/listing_key,_narinfo_type843=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type844=== RUN TestIsValidUploadKey/traversal845=== PAUSE TestIsValidUploadKey/traversal846=== RUN TestIsValidUploadKey/traversal_nar847=== PAUSE TestIsValidUploadKey/traversal_nar848=== RUN TestIsValidUploadKey/absolute849=== PAUSE TestIsValidUploadKey/absolute850=== RUN TestIsValidUploadKey/empty_key851=== PAUSE TestIsValidUploadKey/empty_key852=== RUN TestIsValidUploadKey/unknown_type853=== PAUSE TestIsValidUploadKey/unknown_type854=== CONT TestLeadIncumbentAnnouncesAtOnce855=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure856=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure857=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart858=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart859=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts860=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts861=== CONT TestReadProxyRootRedirectsToIndexHTML862=== CONT TestGCTaskStore_GetReturnsLatest863--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)864=== CONT TestReadProxyConditionalGet865--- PASS: TestReadRedirectKeepsNarinfoProxied (0.93s)8662026/10/09 17:37:54 INFO Received uploads request method=POST path=/api/pending_closures8672026/10/09 17:37:54 INFO Received cleanup request method=DELETE path=/api/pending_closures8682026/10/09 17:37:54 INFO Aborted multipart uploads count=0 kept=08692026/10/09 17:37:54 INFO Received uploads request method=POST path=/api/pending_closures8702026/10/09 17:37:54 INFO Received cleanup request method=DELETE path=/api/pending_closures8712026/10/09 17:37:54 INFO Aborted multipart uploads count=1 kept=08722026/10/09 17:37:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete8732026-10-09 17:37:54.500 UTC [452] ERROR: Closure does not exist: id=18742026-10-09 17:37:54.500 UTC [452] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE8752026-10-09 17:37:54.500 UTC [452] STATEMENT: -- name: CommitPendingClosure :one876 SELECT commit_pending_closure($1::bigint)::bigint877 878--- PASS: TestService_cleanupPendingClosuresHandler (1.03s)879=== CONT TestGCTaskStore_GetEmpty880--- PASS: TestGCTaskStore_GetEmpty (0.00s)881=== CONT TestReadProxyOutlastsServerWriteTimeout882--- PASS: TestReadProxyRangeRequest (1.03s)883=== CONT TestGCTaskStore_ConflictDifferentParams884--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)885=== CONT TestReadProxyHead8862026/10/09 17:37:54 INFO Received uploads request method=POST path=/api/pending_closures8872026/10/09 17:37:54 INFO Received uploads request method=POST path=/api/pending_closures8882026/10/09 17:37:54 INFO Received uploads request method=POST path=/api/pending_closures8892026/10/09 17:37:54 INFO Received push request method=POST path=/api/pushes8902026/10/09 17:37:54 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8912026/10/09 17:37:54 INFO Signed narinfos id=1 count=18922026/10/09 17:37:54 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8932026/10/09 17:37:54 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8942026/10/09 17:37:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8952026/10/09 17:37:54 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst8962026/10/09 17:37:54 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"8972026/10/09 17:37:54 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8982026/10/09 17:37:54 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"8992026/10/09 17:37:54 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign900--- PASS: TestCompleteMultipartUnregistered (1.02s)901=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection9022026/10/09 17:37:54 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19032026/10/09 17:37:54 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9042026/10/09 17:37:54 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo905--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (1.25s)906=== CONT TestReadProxyInvalidPath9072026/10/09 17:37:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9082026/10/09 17:37:54 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWJiY2VjNjQtNzQ4Ni00NWNlLWE0YTAtODU0MDc1Y2I5MDU4LmNkNTlhMjhhLTk3MTAtNGI3Yy1hM2UwLWZmMjhiMDQzOTdiNHgxNzkxNTY3NDc0NTY5NDgyMTIy9092026/10/09 17:37:54 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NWJiY2VjNjQtNzQ4Ni00NWNlLWE0YTAtODU0MDc1Y2I5MDU4LmNkNTlhMjhhLTk3MTAtNGI3Yy1hM2UwLWZmMjhiMDQzOTdiNHgxNzkxNTY3NDc0NTY5NDgyMTIy parts=1910--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (1.33s)911=== CONT TestGCSweepDeliversEachKeyOnce912--- PASS: TestReadProxyDisabled (1.12s)913=== CONT TestReadProxy4049142026/10/09 17:37:54 INFO Received push request method=POST path=/api/pushes9152026/10/09 17:37:54 INFO Received push request method=POST path=/api/pushes9162026/10/09 17:37:54 INFO Received complete push request method=POST path=/api/pushes/1/complete9172026-10-09 17:37:54.909 UTC [510] ERROR: could not obtain lock on row in relation "closures"9182026-10-09 17:37:54.909 UTC [510] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9192026-10-09 17:37:54.909 UTC [510] ERROR: could not obtain lock on row in relation "closures"9202026-10-09 17:37:54.909 UTC [510] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9212026-10-09 17:37:54.910 UTC [510] ERROR: could not obtain lock on row in relation "closures"9222026-10-09 17:37:54.910 UTC [510] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9232026-10-09 17:37:54.910 UTC [510] ERROR: could not obtain lock on row in relation "closures"9242026-10-09 17:37:54.910 UTC [510] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9252026-10-09 17:37:54.910 UTC [510] ERROR: could not obtain lock on row in relation "closures"9262026-10-09 17:37:54.910 UTC [510] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT927--- PASS: TestPush_RootsAreLockedInByteOrder (1.43s)928=== CONT TestTombstonedObjectOfferedWithoutWaiting9292026/10/09 17:37:54 INFO Completed push id=1 objects=6 duration=22.923842ms930--- PASS: TestPush_CompleteCommitsEveryRoot (1.34s)931=== CONT TestReadProxyNarStreaming9322026/10/09 17:37:54 INFO Received uploads request method=POST path=/api/pending_closures933--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.46s)934=== CONT TestGCSweepSkipsPendingObjects9352026/10/09 17:37:54 INFO Received push request method=POST path=/api/pushes9362026/10/09 17:37:55 INFO Received complete push request method=POST path=/api/pushes/1/complete9372026/10/09 17:37:55 INFO Completed push id=1 objects=4 duration=20.798243ms938--- PASS: TestPush_RepeatedRootCommitsOnce (1.46s)939=== CONT TestReadProxyContentNegotiation9402026/10/09 17:37:55 INFO Received uploads request method=POST path=/api/pending_closures9412026/10/09 17:37:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9422026/10/09 17:37:55 INFO Received push request method=POST path=/api/pushes9432026/10/09 17:37:55 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NWJiY2VjNjQtNzQ4Ni00NWNlLWE0YTAtODU0MDc1Y2I5MDU4LmVkOTAyN2M4LTMzOWMtNDBhMC05YjQ3LTllNmYzOTg1Mzk4OHgxNzkxNTY3NDc0NDcxMzcxNjU4 parts=129442026/10/09 17:37:55 INFO Received uploads request method=POST path=/api/pending_closures945--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.68s)946=== CONT TestDeduplicatedObjectsRecordedAsPending947--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (1.58s)948=== CONT TestReadProxyNarinfoAlreadyDecompressed9492026/10/09 17:37:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete950--- PASS: TestReadRedirectUsesPublicS3URL (1.60s)951=== CONT TestPushDedupSurvivesConcurrentGC9522026/10/09 17:37:55 INFO lead: acquired remote=192.0.2.1:12349532026/10/09 17:37:55 INFO lead: released remote=192.0.2.1:1234954--- PASS: TestLeadIncumbentAnnouncesAtOnce (1.35s)955=== CONT TestForceGCDuringPushOffersSweptObject956=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows957=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows958=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check959=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check960=== CONT TestGCMetrics9612026/10/09 17:37:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete962--- PASS: TestReadRedirectNar (1.67s)963=== CONT TestReadProxyNarinfo9642026/10/09 17:37:55 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NWJiY2VjNjQtNzQ4Ni00NWNlLWE0YTAtODU0MDc1Y2I5MDU4LjMzYTljNzQxLTE2OWMtNGVmMi04MTRhLTNmYTkyZjNiMTc2ZXgxNzkxNTY3NDc0NTMyNjQ0MTc4 parts=129652026/10/09 17:37:55 INFO Received uploads request method=POST path=/api/pending_closures9662026/10/09 17:37:55 INFO Received push request method=POST path=/api/pushes9672026/10/09 17:37:55 INFO Received uploads request method=POST path=/api/pending_closures9682026/10/09 17:37:55 INFO Received complete push request method=POST path=/api/pushes/1/complete9692026/10/09 17:37:55 INFO Received uploads request method=POST path=/api/pending_closures9702026/10/09 17:37:55 INFO Completed push id=1 objects=4 duration=21.890273ms9712026/10/09 17:37:55 INFO Received push request method=POST path=/api/pushes9722026/10/09 17:37:55 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9732026/10/09 17:37:55 INFO Received uploads request method=POST path=/api/pending_closures974--- PASS: TestPresignedUploadRegisteredBeforeCommit (1.87s)975=== CONT TestGCBugBareHashReferences976--- PASS: TestService_Rustfstest (1.88s)977=== CONT TestGCTaskStore_DeduplicateSameParams978--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)979=== CONT TestIsValidCachePath980=== RUN TestIsValidCachePath/narinfo981=== PAUSE TestIsValidCachePath/narinfo982=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars983=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars984=== RUN TestIsValidCachePath/nar_zst985=== PAUSE TestIsValidCachePath/nar_zst986=== RUN TestIsValidCachePath/nar_xz987=== PAUSE TestIsValidCachePath/nar_xz988=== RUN TestIsValidCachePath/nar_bz2989=== PAUSE TestIsValidCachePath/nar_bz2990=== RUN TestIsValidCachePath/nar_uncompressed991=== PAUSE TestIsValidCachePath/nar_uncompressed992=== RUN TestIsValidCachePath/ls993=== PAUSE TestIsValidCachePath/ls994=== RUN TestIsValidCachePath/log995=== PAUSE TestIsValidCachePath/log996=== RUN TestIsValidCachePath/realisation997=== PAUSE TestIsValidCachePath/realisation998=== RUN TestIsValidCachePath/nix-cache-info999=== PAUSE TestIsValidCachePath/nix-cache-info1000=== RUN TestIsValidCachePath/index.html1001=== PAUSE TestIsValidCachePath/index.html1002=== RUN TestIsValidCachePath/traversal_parent1003=== PAUSE TestIsValidCachePath/traversal_parent1004=== RUN TestIsValidCachePath/traversal_in_middle1005=== PAUSE TestIsValidCachePath/traversal_in_middle1006=== RUN TestIsValidCachePath/invalid_char_e1007=== PAUSE TestIsValidCachePath/invalid_char_e1008=== RUN TestIsValidCachePath/invalid_char_u1009=== PAUSE TestIsValidCachePath/invalid_char_u1010=== RUN TestIsValidCachePath/random_path1011=== PAUSE TestIsValidCachePath/random_path1012=== RUN TestIsValidCachePath/empty1013=== PAUSE TestIsValidCachePath/empty1014=== RUN TestIsValidCachePath/leading_slash1015=== PAUSE TestIsValidCachePath/leading_slash1016=== RUN TestIsValidCachePath/wrong_extension1017=== PAUSE TestIsValidCachePath/wrong_extension1018=== RUN TestIsValidCachePath/short_hash1019=== PAUSE TestIsValidCachePath/short_hash1020=== CONT TestGCTaskStore_StartNew1021--- PASS: TestGCTaskStore_StartNew (0.00s)1022=== CONT TestGCAdvisoryLockBlocksConcurrentRun1023=== RUN TestPush_RejectsBadRequests/bad_root1024=== PAUSE TestPush_RejectsBadRequests/bad_root1025=== RUN TestPush_RejectsBadRequests/root_not_in_objects1026=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1027=== RUN TestPush_RejectsBadRequests/no_roots1028=== PAUSE TestPush_RejectsBadRequests/no_roots1029=== RUN TestPush_RejectsBadRequests/no_objects1030=== PAUSE TestPush_RejectsBadRequests/no_objects1031=== CONT TestParseSingleRange1032=== RUN TestParseSingleRange/none1033=== PAUSE TestParseSingleRange/none1034=== RUN TestParseSingleRange/unknown_unit1035=== PAUSE TestParseSingleRange/unknown_unit1036=== RUN TestParseSingleRange/multi-range_ignored1037=== PAUSE TestParseSingleRange/multi-range_ignored1038=== RUN TestParseSingleRange/malformed_no_dash1039=== PAUSE TestParseSingleRange/malformed_no_dash1040=== RUN TestParseSingleRange/malformed_both_empty1041=== PAUSE TestParseSingleRange/malformed_both_empty1042=== RUN TestParseSingleRange/malformed_end_before_start1043=== PAUSE TestParseSingleRange/malformed_end_before_start1044=== RUN TestParseSingleRange/closed1045=== PAUSE TestParseSingleRange/closed1046=== RUN TestParseSingleRange/open-ended1047=== PAUSE TestParseSingleRange/open-ended1048=== RUN TestParseSingleRange/end_clamped_to_size1049=== PAUSE TestParseSingleRange/end_clamped_to_size1050=== RUN TestParseSingleRange/suffix1051=== PAUSE TestParseSingleRange/suffix1052=== RUN TestParseSingleRange/suffix_exceeds_size1053=== PAUSE TestParseSingleRange/suffix_exceeds_size1054=== RUN TestParseSingleRange/single_byte1055=== PAUSE TestParseSingleRange/single_byte1056=== RUN TestParseSingleRange/start_past_EOF1057=== PAUSE TestParseSingleRange/start_past_EOF1058=== RUN TestParseSingleRange/start_far_past_EOF1059=== PAUSE TestParseSingleRange/start_far_past_EOF1060=== CONT TestGCEndsOnShutdown1061=== RUN TestGCEndsOnShutdown/before_the_run1062=== PAUSE TestGCEndsOnShutdown/before_the_run1063=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1064=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1065=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1066=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1067=== CONT TestLeadEndsOnShutdown10682026/10/09 17:37:55 INFO Aborted multipart uploads count=0 kept=010692026/10/09 17:37:55 WARN Force mode enabled - objects will be deleted immediately without grace period1070--- PASS: TestReadProxyRootRedirectsToIndexHTML (1.45s)1071=== CONT TestPresentNotReportedWhileGCDeletesClosure1072=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1073=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1074=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1075=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1076=== CONT TestCommitRacingPendingCleanupKeepsObjects10772026/10/09 17:37:55 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=010782026/10/09 17:37:55 INFO Vacuumed table table=pending_closures10792026/10/09 17:37:55 INFO Vacuumed table table=pending_objects10802026/10/09 17:37:55 INFO Received push request method=POST path=/api/pushes10812026/10/09 17:37:55 INFO Vacuumed table table=multipart_uploads10822026/10/09 17:37:55 INFO Vacuumed table table=closures10832026/10/09 17:37:55 INFO Vacuumed table table=objects10842026/10/09 17:37:55 INFO Received complete push request method=POST path=/api/pushes/2/complete10852026/10/09 17:37:55 INFO Completed push id=2 objects=4 duration=8.231212ms1086--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.99s)1087=== CONT TestPresentRefreshesOnlyStaleClosures1088--- PASS: TestReadProxyConditionalGet (1.09s)1089=== CONT TestPushWaitsForSweepHoldingRow1090--- PASS: TestReadProxyHead (1.01s)1091=== CONT TestClientMultipleUploads10922026/10/09 17:37:55 INFO Received uploads request method=POST path=/api/pending_closures1093--- PASS: TestReadProxyInvalidPath (0.88s)1094=== CONT TestPresentReportsOnlyClosureRoots10952026/10/09 17:37:55 INFO Aborted multipart uploads count=0 kept=010962026/10/09 17:37:55 WARN Force mode enabled - objects will be deleted immediately without grace period10972026/10/09 17:37:55 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=010982026/10/09 17:37:55 INFO Vacuumed table table=pending_closures10992026/10/09 17:37:55 INFO Received uploads request method=POST path=/api/pending_closures11002026/10/09 17:37:55 INFO Vacuumed table table=pending_objects11012026/10/09 17:37:55 INFO Vacuumed table table=multipart_uploads11022026/10/09 17:37:55 INFO Vacuumed table table=closures11032026/10/09 17:37:55 INFO Vacuumed table table=objects1104--- PASS: TestGCSweepDeliversEachKeyOnce (0.95s)1105=== CONT TestSweepRechecksPendingAfterLocking1106--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.84s)1107=== CONT TestLeadScopedToFarm11082026-10-09 17:37:55.775 UTC [572] ERROR: Push does not exist: id=111092026-10-09 17:37:55.775 UTC [572] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11102026-10-09 17:37:55.775 UTC [572] STATEMENT: SELECT commit_push($1)1111--- PASS: TestReadProxy404 (0.96s)1112=== CONT TestGetExistingObjectsLocksRows1113--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (2.29s)1114=== CONT TestLeadElectsOneAndHandsOver1115--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.07s)1116=== CONT TestRegisterCompletedObjectNeedsPendingRow1117--- PASS: TestReadProxyNarStreaming (0.86s)1118=== CONT TestConnectWaitsForAPeerMigration11192026/10/09 17:37:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11202026/10/09 17:37:55 INFO Received uploads request method=POST path=/api/pending_closures11212026/10/09 17:37:55 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NWJiY2VjNjQtNzQ4Ni00NWNlLWE0YTAtODU0MDc1Y2I5MDU4LmM0OGU1Yjg4LTI5ZTQtNDY4ZC1hMWRhLTdhNjUyOTYwNGY4NHgxNzkxNTY3NDc1MzA2NzE2MzM0 error="Get \"http://127.0.0.1:1/bucket8/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11222026/10/09 17:37:55 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NWJiY2VjNjQtNzQ4Ni00NWNlLWE0YTAtODU0MDc1Y2I5MDU4LmY5ODQwNjBlLWE4MWYtNGNmNy1iMjAyLTZjNzhkNjQ4MGI2YXgxNzkxNTY3NDc1Mjg1MDczMjIz parts=1211232026/10/09 17:37:55 INFO Received cleanup request method=DELETE path=/api/pending_closures11242026/10/09 17:37:55 INFO Aborted multipart uploads count=1 kept=011252026/10/09 17:37:55 INFO Aborted multipart uploads count=0 kept=01126--- PASS: TestRedundantMultipartUpload (2.39s)1127=== CONT TestCreatePin_ReservedPins11282026/10/09 17:37:55 WARN Force mode enabled - objects will be deleted immediately without grace period11292026/10/09 17:37:55 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=011302026/10/09 17:37:55 INFO Vacuumed table table=pending_closures1131--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.75s)1132=== CONT TestResolveDBConnectionString1133=== RUN TestResolveDBConnectionString/flag_wins1134=== PAUSE TestResolveDBConnectionString/flag_wins1135=== RUN TestResolveDBConnectionString/file_when_flag_empty1136=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1137=== RUN TestResolveDBConnectionString/missing_file_is_an_error1138=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1139=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1140=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1141=== RUN TestResolveDBConnectionString/nothing_configured1142=== PAUSE TestResolveDBConnectionString/nothing_configured1143=== CONT TestSweepSkipsRowsLockedByPush11442026/10/09 17:37:55 INFO Vacuumed table table=pending_objects11452026/10/09 17:37:55 INFO Vacuumed table table=multipart_uploads11462026/10/09 17:37:55 INFO Vacuumed table table=closures11472026/10/09 17:37:55 INFO Vacuumed table table=objects1148--- PASS: TestGCSweepSkipsPendingObjects (0.98s)1149=== CONT TestOrphanedObjectsGCStressTest11502026/10/09 17:37:55 INFO Received uploads request method=POST path=/api/pending_closures1151--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.82s)1152=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1153--- PASS: TestReadProxyContentNegotiation (0.94s)1154=== CONT TestFailedS3DeleteKeepsTombstone11552026/10/09 17:37:56 INFO Received uploads request method=POST path=/api/pending_closures11562026/10/09 17:37:56 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34969/oidc11572026/10/09 17:37:56 INFO Aborted multipart uploads count=0 kept=011582026/10/09 17:37:56 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"1159--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.74s)1160=== CONT TestOrphanedObjectsGC11612026/10/09 17:37:56 INFO Aborted multipart uploads count=0 kept=011622026/10/09 17:37:56 INFO lead: acquired remote=192.0.2.1:123411632026/10/09 17:37:56 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1164--- PASS: TestReadProxyNarinfo (0.90s)1165=== CONT TestDeleteClosuresRacingPins1166--- PASS: TestPresentRefreshesOnlyStaleClosures (0.69s)1167=== CONT TestObjectStatsLargeCommit11682026/10/09 17:37:56 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=011692026/10/09 17:37:56 INFO Vacuumed table table=pending_closures11702026/10/09 17:37:56 INFO Vacuumed table table=pending_objects11712026/10/09 17:37:56 INFO Vacuumed table table=multipart_uploads11722026/10/09 17:37:56 INFO Vacuumed table table=closures11732026/10/09 17:37:56 INFO Vacuumed table table=objects11742026/10/09 17:37:56 INFO Aborted multipart uploads count=0 kept=011752026/10/09 17:37:56 WARN Force mode enabled - objects will be deleted immediately without grace period11762026/10/09 17:37:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011772026/10/09 17:37:56 INFO Received uploads request method=POST path=/api/pending_closures11782026/10/09 17:37:56 INFO Vacuumed table table=pending_closures11792026/10/09 17:37:56 INFO Vacuumed table table=pending_objects11802026/10/09 17:37:56 INFO Vacuumed table table=multipart_uploads11812026/10/09 17:37:56 INFO Aborted multipart uploads count=0 kept=011822026/10/09 17:37:56 INFO Vacuumed table table=closures11832026/10/09 17:37:56 INFO Vacuumed table table=objects1184--- PASS: TestPushDedupSurvivesConcurrentGC (1.03s)1185=== CONT TestService_verifyS3Integrity11862026/10/09 17:37:56 WARN Force mode enabled - objects will be deleted immediately without grace period11872026/10/09 17:37:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011882026/10/09 17:37:56 INFO Vacuumed table table=pending_closures11892026/10/09 17:37:56 INFO Vacuumed table table=pending_objects11902026/10/09 17:37:56 INFO Vacuumed table table=multipart_uploads11912026/10/09 17:37:56 INFO Vacuumed table table=closures11922026/10/09 17:37:56 INFO Vacuumed table table=objects1193--- PASS: TestGCMetrics (1.05s)1194=== CONT TestObjectStatsTrigger1195--- PASS: TestPresentReportsOnlyClosureRoots (0.67s)1196=== CONT TestClientFallsBackToClosures1197=== NAME TestClientMultipleUploads1198 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads1792093354/001/store/q241yk9ms05jk6f3iyba0iihkdkk0h50-test-file-0.txt11992026/10/09 17:37:56 INFO lead: acquired remote=192.0.2.1:123412002026/10/09 17:37:56 INFO Aborted multipart uploads count=0 kept=01201--- PASS: TestGetExistingObjectsLocksRows (0.58s)1202=== CONT TestPinProtectsFromGC1203--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.57s)1204=== CONT TestCreatePendingClosureRejectsOversizedNAR12052026/10/09 17:37:56 INFO Received uploads request method=POST path=/api/pending_closures1206--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1207=== CONT TestClientSharedPathCommittedMidPush12082026/10/09 17:37:56 INFO lead: acquired remote=192.0.2.1:123412092026/10/09 17:37:56 INFO lead: acquired remote=192.0.2.1:123412102026/10/09 17:37:56 INFO lead: acquired remote=192.0.2.1:123412112026/10/09 17:37:56 INFO lead: released remote=192.0.2.1:123412122026/10/09 17:37:56 INFO Aborted multipart uploads count=0 kept=01213--- PASS: TestGCBugBareHashReferences (1.10s)1214=== CONT TestClientPushesUseOnePush12152026/10/09 17:37:56 INFO lead: acquired remote=192.0.2.1:123412162026/10/09 17:37:56 INFO lead: released remote=192.0.2.1:123412172026/10/09 17:37:56 INFO lead: released remote=192.0.2.1:123412182026/10/09 17:37:56 INFO lead: released remote=192.0.2.1:12341219--- PASS: TestLeadScopedToFarm (0.69s)1220=== CONT TestCacheConfigHandlerMaxNarSize1221--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1222=== CONT TestClientWithDependencies1223=== NAME TestClientMultipleUploads1224 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads1792093354/001/store/yk6lg7mxc5gc6gaga6glmwfyzdn3dfdn-test-file-1.txt12252026/10/09 17:37:56 WARN Force mode enabled - objects will be deleted immediately without grace period12262026/10/09 17:37:56 INFO Received uploads request method=POST path=/api/pending_closures12272026/10/09 17:37:56 WARN Force mode enabled - objects will be deleted immediately without grace period12282026/10/09 17:37:56 WARN Force mode enabled - objects will be deleted immediately without grace period1229 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads1792093354/001/store/5xcj53wr7671sk475vdjv164c0ns5vwd-test-file-2.txt12302026/10/09 17:37:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012312026/10/09 17:37:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012322026/10/09 17:37:56 INFO Vacuumed table table=pending_closures12332026/10/09 17:37:56 INFO Vacuumed table table=pending_objects12342026/10/09 17:37:56 INFO Vacuumed table table=multipart_uploads12352026/10/09 17:37:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012362026/10/09 17:37:56 INFO Vacuumed table table=closures12372026/10/09 17:37:56 INFO Vacuumed table table=pending_closures12382026/10/09 17:37:56 INFO Vacuumed table table=pending_objects12392026/10/09 17:37:56 INFO Vacuumed table table=multipart_uploads12402026/10/09 17:37:56 INFO Vacuumed table table=pending_closures12412026/10/09 17:37:56 INFO Vacuumed table table=closures12422026/10/09 17:37:56 INFO Vacuumed table table=objects12432026/10/09 17:37:56 INFO Vacuumed table table=objects12442026/10/09 17:37:56 INFO Vacuumed table table=pending_objects12452026/10/09 17:37:56 INFO Vacuumed table table=multipart_uploads12462026/10/09 17:37:56 INFO Vacuumed table table=closures12472026/10/09 17:37:56 INFO Aborted multipart uploads count=0 kept=012482026/10/09 17:37:56 WARN Force mode enabled - objects will be deleted immediately without grace period12492026/10/09 17:37:56 INFO Vacuumed table table=objects1250--- PASS: TestSweepRechecksPendingAfterLocking (0.78s)1251=== CONT TestGenerateLandingPage1252--- PASS: TestGenerateLandingPage (0.00s)1253=== CONT TestServerTLSConfig1254=== RUN TestServerTLSConfig/no_client_CA1255=== PAUSE TestServerTLSConfig/no_client_CA1256=== RUN TestServerTLSConfig/missing_CA_file1257=== PAUSE TestServerTLSConfig/missing_CA_file1258=== RUN TestServerTLSConfig/not_a_PEM_file1259=== PAUSE TestServerTLSConfig/not_a_PEM_file1260=== CONT TestService_createPendingClosureHandler12612026/10/09 17:37:56 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=1 objects-failed-to-delete=012622026/10/09 17:37:56 INFO Vacuumed table table=pending_closures12632026/10/09 17:37:56 INFO Vacuumed table table=pending_objects12642026/10/09 17:37:56 INFO Vacuumed table table=multipart_uploads1265--- PASS: TestCommitRacingPendingCleanupKeepsObjects (1.14s)1266=== CONT TestService_readinessHandler12672026/10/09 17:37:56 INFO Vacuumed table table=closures12682026/10/09 17:37:56 INFO Vacuumed table table=objects1269--- PASS: TestSweepSkipsRowsLockedByPush (0.65s)1270=== CONT TestPendingCleanupUsesOneCutoff12712026/10/09 17:37:56 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12722026/10/09 17:37:56 WARN Refused reserved pin name=worker-x86_64-linux12732026/10/09 17:37:56 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12742026/10/09 17:37:56 INFO Received create pin request method=POST path=/api/pins/my-app12752026/10/09 17:37:56 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1276--- PASS: TestCreatePin_ReservedPins (0.74s)1277=== CONT TestGracefulShutdownDrainsInflight12782026/10/09 17:37:56 INFO Starting HTTP server address=127.0.0.1:4435712792026/10/09 17:37:56 INFO Shutdown signal received, draining in-flight requests timeout=10s12802026/10/09 17:37:56 INFO Aborted multipart uploads count=0 kept=012812026/10/09 17:37:56 WARN Force mode enabled - objects will be deleted immediately without grace period12822026/10/09 17:37:56 INFO Received uploads request method=POST path=/api/pending_closures12832026/10/09 17:37:56 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12842026/10/09 17:37:56 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1285--- PASS: TestFailedS3DeleteKeepsTombstone (0.66s)1286=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded12872026/10/09 17:37:56 INFO Received push request method=POST path=/api/pushes12882026/10/09 17:37:56 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)12892026/10/09 17:37:56 INFO Uploading q241yk9ms05jk6f3iyba0iihkdkk0h50-test-file-0.txt (160B)12902026/10/09 17:37:56 INFO Uploading yk6lg7mxc5gc6gaga6glmwfyzdn3dfdn-test-file-1.txt (160B)12912026/10/09 17:37:56 INFO Uploading 5xcj53wr7671sk475vdjv164c0ns5vwd-test-file-2.txt (160B)1292--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1293=== CONT TestGCTaskStore_Fail1294--- PASS: TestGCTaskStore_Fail (0.00s)1295=== CONT TestMultipartCleanup12962026/10/09 17:37:56 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"12972026/10/09 17:37:56 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"12982026/10/09 17:37:56 WARN Failed to register uploaded object key=5xcj53wr7671sk475vdjv164c0ns5vwd.ls error="server returned 404: 404 page not found\n"12992026/10/09 17:37:56 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"13002026/10/09 17:37:56 WARN Failed to register uploaded object key=yk6lg7mxc5gc6gaga6glmwfyzdn3dfdn.ls error="server returned 404: 404 page not found\n"13012026/10/09 17:37:56 WARN Failed to register uploaded object key=q241yk9ms05jk6f3iyba0iihkdkk0h50.ls error="server returned 404: 404 page not found\n"13022026/10/09 17:37:56 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13032026/10/09 17:37:56 INFO Signed narinfos id=1 count=313042026/10/09 17:37:56 INFO Uploading 3 narinfos13052026/10/09 17:37:56 WARN Failed to register uploaded object key=yk6lg7mxc5gc6gaga6glmwfyzdn3dfdn.narinfo error="server returned 404: 404 page not found\n"13062026/10/09 17:37:56 WARN Failed to register uploaded object key=q241yk9ms05jk6f3iyba0iihkdkk0h50.narinfo error="server returned 404: 404 page not found\n"13072026/10/09 17:37:56 INFO Received complete push request method=POST path=/api/pushes/1/complete13082026/10/09 17:37:56 WARN Failed to register uploaded object key=5xcj53wr7671sk475vdjv164c0ns5vwd.narinfo error="server returned 404: 404 page not found\n"13092026/10/09 17:37:56 INFO Completed push id=1 objects=9 duration=11.204899ms13102026/10/09 17:37:56 INFO Upload complete. (111ms)1311=== NAME TestClientMultipleUploads1312 client_integration_test.go:369: Uploaded 3 paths in 185.825477ms1313--- PASS: TestClientMultipleUploads (1.19s)1314=== CONT TestService_healthCheckHandler1315--- PASS: TestPushWaitsForSweepHoldingRow (1.21s)1316=== CONT TestGCTaskStore_PhaseUpdates1317--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1318=== CONT TestService_ReadScope_PublicByDefault1319--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.83s)1320=== CONT TestService_ReadAuthMiddleware1321--- PASS: TestObjectStatsTrigger (0.56s)1322=== CONT TestClientIntegration1323=== NAME TestOrphanedObjectsGC1324 orphaned_objects_gc_test.go:287: GC Test Summary:1325 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1326 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1327 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1328 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1329 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1330--- PASS: TestOrphanedObjectsGC (0.86s)1331=== CONT TestService_AuthMiddleware_MTLSProxyHeader1332=== NAME TestPinProtectsFromGC1333 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC1507603535/001/store/qhddpykw2h291raqifm41b75p6dnvjda-pinned-file.txt1334 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC1507603535/001/store/b14q2gbbqhg6kxfgsyj467z4nl06yxlx-unpinned-file.txt13352026/10/09 17:37:56 INFO Received uploads request method=POST path=/api/pending_closures13362026/10/09 17:37:56 INFO Received uploads request method=POST path=/api/pending_closures13372026/10/09 17:37:56 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13382026/10/09 17:37:56 INFO Uploading y6aaiy07d1vg0fbsk7sbvvr6d78ndkgx-shared-dep (136B)13392026/10/09 17:37:56 INFO Uploading qzi66r0mz7nr3bwd0pv95fr99g32g02i-b (216B)13402026/10/09 17:37:57 WARN Failed to register uploaded object key=y6aaiy07d1vg0fbsk7sbvvr6d78ndkgx.ls error="server returned 404: 404 page not found\n"13412026/10/09 17:37:57 WARN Failed to register uploaded object key=qzi66r0mz7nr3bwd0pv95fr99g32g02i.ls error="server returned 404: 404 page not found\n"13422026/10/09 17:37:57 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13432026/10/09 17:37:57 WARN Failed to register uploaded object key=0s5lvi69hp8n5yaz9g9sgjifj0y68lck.ls error="server returned 404: 404 page not found\n"13442026/10/09 17:37:57 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13452026/10/09 17:37:57 WARN Failed to register uploaded object key=nar/0q8x696isb789iv99iz0wd4y00qs4d97hrls2vfbajfi719nygvf.nar.zst error="server returned 404: 404 page not found\n"13462026/10/09 17:37:57 INFO Signed narinfos id=1 count=213472026/10/09 17:37:57 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13482026/10/09 17:37:57 INFO Signed narinfos id=2 count=213492026/10/09 17:37:57 INFO Uploading 4 narinfos13502026/10/09 17:37:57 WARN Failed to register uploaded object key=qzi66r0mz7nr3bwd0pv95fr99g32g02i.narinfo error="server returned 404: 404 page not found\n"13512026/10/09 17:37:57 WARN Failed to register uploaded object key=y6aaiy07d1vg0fbsk7sbvvr6d78ndkgx.narinfo error="server returned 404: 404 page not found\n"13522026/10/09 17:37:57 WARN Failed to register uploaded object key=0s5lvi69hp8n5yaz9g9sgjifj0y68lck.narinfo error="server returned 404: 404 page not found\n"13532026/10/09 17:37:57 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13542026/10/09 17:37:57 WARN Failed to register uploaded object key=y6aaiy07d1vg0fbsk7sbvvr6d78ndkgx.narinfo error="server returned 404: 404 page not found\n"13552026/10/09 17:37:57 INFO Completed upload id=2 objects=6 duration=7.916089ms13562026/10/09 17:37:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13572026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures13582026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures13592026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures13602026/10/09 17:37:57 INFO Completed upload id=1 objects=6 duration=3.529891ms13612026/10/09 17:37:57 INFO Upload complete. (110ms)1362=== NAME TestClientFallsBackToClosures1363 client_pushes_test.go:112: Retrieved narinfo from S3:1364 StorePath: /build/TestClientFallsBackToClosures2704265863/001/store/y6aaiy07d1vg0fbsk7sbvvr6d78ndkgx-shared-dep1365 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1366 Compression: zstd1367 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821368 NarSize: 1361369 References: 1370 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1371 client_pushes_test.go:112: Retrieved narinfo from S3:1372 StorePath: /build/TestClientFallsBackToClosures2704265863/001/store/0s5lvi69hp8n5yaz9g9sgjifj0y68lck-a1373 URL: nar/0q8x696isb789iv99iz0wd4y00qs4d97hrls2vfbajfi719nygvf.nar.zst1374 Compression: zstd1375 NarHash: sha256:0q8x696isb789iv99iz0wd4y00qs4d97hrls2vfbajfi719nygvf1376 NarSize: 2161377 References: /build/TestClientFallsBackToClosures2704265863/001/store/y6aaiy07d1vg0fbsk7sbvvr6d78ndkgx-shared-dep1378 CA: text:sha256:1yhh4p7mzj7x2f5l7hhq3fdkkqrqwga1hjsb41kqq9jdgzs5hysj1379 client_pushes_test.go:112: Retrieved narinfo from S3:1380 StorePath: /build/TestClientFallsBackToClosures2704265863/001/store/qzi66r0mz7nr3bwd0pv95fr99g32g02i-b1381 URL: nar/0q8x696isb789iv99iz0wd4y00qs4d97hrls2vfbajfi719nygvf.nar.zst1382 Compression: zstd1383 NarHash: sha256:0q8x696isb789iv99iz0wd4y00qs4d97hrls2vfbajfi719nygvf1384 NarSize: 2161385 References: /build/TestClientFallsBackToClosures2704265863/001/store/y6aaiy07d1vg0fbsk7sbvvr6d78ndkgx-shared-dep1386 CA: text:sha256:1yhh4p7mzj7x2f5l7hhq3fdkkqrqwga1hjsb41kqq9jdgzs5hysj1387--- PASS: TestClientFallsBackToClosures (0.77s)1388=== CONT TestService_RequireScope_OIDC13892026/10/09 17:37:57 WARN readiness check failed error="closed pool"1390--- PASS: TestService_readinessHandler (0.50s)1391=== CONT TestClientErrorHandling1392=== RUN TestClientErrorHandling/InvalidStorePath1393=== PAUSE TestClientErrorHandling/InvalidStorePath1394=== RUN TestClientErrorHandling/InvalidAuthToken1395=== PAUSE TestClientErrorHandling/InvalidAuthToken1396=== RUN TestClientErrorHandling/ServerNotAvailable1397=== PAUSE TestClientErrorHandling/ServerNotAvailable1398=== CONT TestService_AuthMiddleware_MTLSBoundSubjects13992026/10/09 17:37:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14002026/10/09 17:37:57 INFO Received push request method=POST path=/api/pushes14012026/10/09 17:37:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14022026/10/09 17:37:57 INFO Uploading qhddpykw2h291raqifm41b75p6dnvjda-pinned-file.txt (128B)14032026/10/09 17:37:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14042026/10/09 17:37:57 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14052026/10/09 17:37:57 WARN Failed to register uploaded object key=qhddpykw2h291raqifm41b75p6dnvjda.ls error="server returned 404: 404 page not found\n"14062026/10/09 17:37:57 INFO Signed narinfos id=1 count=114072026/10/09 17:37:57 INFO Uploading 1 narinfos14082026/10/09 17:37:57 INFO Received complete push request method=POST path=/api/pushes/1/complete14092026/10/09 17:37:57 WARN Failed to register uploaded object key=qhddpykw2h291raqifm41b75p6dnvjda.narinfo error="server returned 404: 404 page not found\n"1410=== NAME TestClientWithDependencies1411 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies1578189084/001/store/1njg1q1in1q8bbqk91kx8z3pdmlqinh5-test-script14122026/10/09 17:37:57 INFO Completed push id=1 objects=3 duration=13.980483ms14132026/10/09 17:37:57 INFO Upload complete. (95ms)14142026/10/09 17:37:57 INFO Received push request method=POST path=/api/pushes14152026/10/09 17:37:57 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14162026/10/09 17:37:57 INFO Uploading srppb1fzsjawzfz7z9pahwkzw5yxcn6y-top (224B)14172026/10/09 17:37:57 INFO Uploading hkhgl2w6h77i9naqf67sgvjl784g396r-shared-dep (136B)14182026/10/09 17:37:57 INFO lead: released remote=192.0.2.1:12341419--- PASS: TestLeadEndsOnShutdown (1.78s)1420=== CONT TestService_AuthMiddleware_OIDC14212026/10/09 17:37:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45011/oidc1422=== NAME TestClientWithDependencies1423 client_integration_test.go:615: Found 1 dependencies (including self)14242026/10/09 17:37:57 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14252026/10/09 17:37:57 WARN Failed to register uploaded object key=nar/1vk8wg2sxwfvri7rra7llc63l82dz2fvvlnn8dninbfddyyfn400.nar.zst error="server returned 404: 404 page not found\n"14262026/10/09 17:37:57 INFO Received push request method=POST path=/api/pushes14272026/10/09 17:37:57 WARN Failed to register uploaded object key=srppb1fzsjawzfz7z9pahwkzw5yxcn6y.ls error="server returned 404: 404 page not found\n"14282026/10/09 17:37:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14292026/10/09 17:37:57 WARN Failed to register uploaded object key=hkhgl2w6h77i9naqf67sgvjl784g396r.ls error="server returned 404: 404 page not found\n"14302026/10/09 17:37:57 INFO Signed narinfos id=1 count=214312026/10/09 17:37:57 INFO Uploading 2 narinfos14322026/10/09 17:37:57 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14332026/10/09 17:37:57 INFO Uploading 3sk8qpdrfggwy2qhkimwxdckyzpzlx4l-shared-dep (136B)14342026/10/09 17:37:57 INFO Received complete push request method=POST path=/api/pushes/1/complete14352026/10/09 17:37:57 WARN Failed to register uploaded object key=hkhgl2w6h77i9naqf67sgvjl784g396r.narinfo error="server returned 404: 404 page not found\n"14362026/10/09 17:37:57 INFO Uploading pnr3fzb1f8dv4kpzql4c46kq5jjgp13d-b (216B)14372026/10/09 17:37:57 WARN Failed to register uploaded object key=srppb1fzsjawzfz7z9pahwkzw5yxcn6y.narinfo error="server returned 404: 404 page not found\n"14382026/10/09 17:37:57 WARN Failed to register uploaded object key=zh8l3y5v44idw7fq6ncs46hhcdfbaj6j.ls error="server returned 404: 404 page not found\n"14392026/10/09 17:37:57 WARN Failed to register uploaded object key=pnr3fzb1f8dv4kpzql4c46kq5jjgp13d.ls error="server returned 404: 404 page not found\n"14402026/10/09 17:37:57 WARN Failed to register uploaded object key=nar/1m6r3x9v32m8sbayf7cdrrgrxrzjs8hmkcb6sgvmigmj1svcq7hg.nar.zst error="server returned 404: 404 page not found\n"14412026/10/09 17:37:57 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14422026/10/09 17:37:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14432026/10/09 17:37:57 WARN Failed to register uploaded object key=3sk8qpdrfggwy2qhkimwxdckyzpzlx4l.ls error="server returned 404: 404 page not found\n"14442026/10/09 17:37:57 INFO Signed narinfos id=1 count=314452026/10/09 17:37:57 INFO Uploading 3 narinfos14462026/10/09 17:37:57 INFO Completed push id=1 objects=6 duration=8.986019ms14472026/10/09 17:37:57 INFO Upload complete. (143ms)1448=== NAME TestClientSharedPathCommittedMidPush1449 client_integration_test.go:680: Retrieved narinfo from S3:1450 StorePath: /build/TestClientSharedPathCommittedMidPush3147211768/001/store/hkhgl2w6h77i9naqf67sgvjl784g396r-shared-dep1451 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1452 Compression: zstd1453 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821454 NarSize: 1361455 References: 1456 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n14572026/10/09 17:37:57 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NWJiY2VjNjQtNzQ4Ni00NWNlLWE0YTAtODU0MDc1Y2I5MDU4LjQxYTcxODdjLTJiM2MtNGVlMC1hMTRkLWViZWUzMTQwM2ZkZngxNzkxNTY3NDc2NjQyODkyNDc5 parts=1014582026/10/09 17:37:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete14592026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures14602026/10/09 17:37:57 WARN Failed to register uploaded object key=zh8l3y5v44idw7fq6ncs46hhcdfbaj6j.narinfo error="server returned 404: 404 page not found\n"14612026/10/09 17:37:57 WARN Failed to register uploaded object key=3sk8qpdrfggwy2qhkimwxdckyzpzlx4l.narinfo error="server returned 404: 404 page not found\n"14622026/10/09 17:37:57 INFO Received complete push request method=POST path=/api/pushes/1/complete14632026/10/09 17:37:57 WARN Failed to register uploaded object key=pnr3fzb1f8dv4kpzql4c46kq5jjgp13d.narinfo error="server returned 404: 404 page not found\n"1464 client_integration_test.go:680: Retrieved narinfo from S3:1465 StorePath: /build/TestClientSharedPathCommittedMidPush3147211768/001/store/srppb1fzsjawzfz7z9pahwkzw5yxcn6y-top1466 URL: nar/1vk8wg2sxwfvri7rra7llc63l82dz2fvvlnn8dninbfddyyfn400.nar.zst1467 Compression: zstd1468 NarHash: sha256:1vk8wg2sxwfvri7rra7llc63l82dz2fvvlnn8dninbfddyyfn4001469 NarSize: 2241470 References: /build/TestClientSharedPathCommittedMidPush3147211768/001/store/hkhgl2w6h77i9naqf67sgvjl784g396r-shared-dep1471 CA: text:sha256:0kzchwnf0vbn3blaachkjfq6z1cpyjmq8a9h882b816yv748qgmp14722026/10/09 17:37:57 INFO Completed upload id=1 objects=2 duration=6.118814ms14732026/10/09 17:37:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36549/oidc14742026/10/09 17:37:57 INFO Completed push id=1 objects=8 duration=7.610547ms14752026/10/09 17:37:57 INFO Upload complete. (98ms)1476--- PASS: TestClientSharedPathCommittedMidPush (0.86s)1477=== CONT TestNARDeduplicationMetadataUploadBug14782026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures1479=== NAME TestClientPushesUseOnePush1480 client_pushes_test.go:97: Retrieved narinfo from S3:1481 StorePath: /build/TestClientPushesUseOnePush2661786812/001/store/3sk8qpdrfggwy2qhkimwxdckyzpzlx4l-shared-dep1482 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1483 Compression: zstd1484 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821485 NarSize: 1361486 References: 1487 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n14882026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures1489 client_pushes_test.go:97: Retrieved narinfo from S3:14902026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures1491 StorePath: /build/TestClientPushesUseOnePush2661786812/001/store/zh8l3y5v44idw7fq6ncs46hhcdfbaj6j-a1492 URL: nar/1m6r3x9v32m8sbayf7cdrrgrxrzjs8hmkcb6sgvmigmj1svcq7hg.nar.zst1493 Compression: zstd1494 NarHash: sha256:1m6r3x9v32m8sbayf7cdrrgrxrzjs8hmkcb6sgvmigmj1svcq7hg1495 NarSize: 2161496 References: /build/TestClientPushesUseOnePush2661786812/001/store/3sk8qpdrfggwy2qhkimwxdckyzpzlx4l-shared-dep1497 CA: text:sha256:09jrfr44ikmzrkgc9hzns4yjbp01047xh8cqhmvxca9yjwapyqs614982026/10/09 17:37:57 INFO Received push request method=POST path=/api/pushes14992026/10/09 17:37:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15002026/10/09 17:37:57 INFO Uploading b14q2gbbqhg6kxfgsyj467z4nl06yxlx-unpinned-file.txt (128B)15012026/10/09 17:37:57 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo15022026/10/09 17:37:57 WARN Found objects in DB but missing from S3, will re-upload count=11503 client_pushes_test.go:97: Retrieved narinfo from S3:1504 StorePath: /build/TestClientPushesUseOnePush2661786812/001/store/pnr3fzb1f8dv4kpzql4c46kq5jjgp13d-b1505 URL: nar/1m6r3x9v32m8sbayf7cdrrgrxrzjs8hmkcb6sgvmigmj1svcq7hg.nar.zst1506 Compression: zstd1507 NarHash: sha256:1m6r3x9v32m8sbayf7cdrrgrxrzjs8hmkcb6sgvmigmj1svcq7hg1508 NarSize: 2161509 References: /build/TestClientPushesUseOnePush2661786812/001/store/3sk8qpdrfggwy2qhkimwxdckyzpzlx4l-shared-dep1510 CA: text:sha256:09jrfr44ikmzrkgc9hzns4yjbp01047xh8cqhmvxca9yjwapyqs61511--- PASS: TestService_verifyS3Integrity (1.02s)1512=== CONT TestCacheStatsHandler15132026/10/09 17:37:57 WARN Failed to register uploaded object key=b14q2gbbqhg6kxfgsyj467z4nl06yxlx.ls error="server returned 404: 404 page not found\n"1514--- PASS: TestClientPushesUseOnePush (0.80s)1515=== CONT TestMetricsCommit15162026/10/09 17:37:57 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15172026/10/09 17:37:57 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"15182026/10/09 17:37:57 INFO Signed narinfos id=2 count=115192026/10/09 17:37:57 INFO Uploading 1 narinfos15202026/10/09 17:37:57 INFO Received cleanup request method=DELETE path=/api/pending_closures15212026/10/09 17:37:57 INFO Received complete push request method=POST path=/api/pushes/2/complete15222026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures15232026/10/09 17:37:57 WARN Failed to register uploaded object key=b14q2gbbqhg6kxfgsyj467z4nl06yxlx.narinfo error="server returned 404: 404 page not found\n"15242026/10/09 17:37:57 INFO Completed push id=2 objects=3 duration=14.85507ms15252026/10/09 17:37:57 INFO Upload complete. (72ms)15262026/10/09 17:37:57 INFO Received push request method=POST path=/api/pushes15272026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures15282026/10/09 17:37:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15292026/10/09 17:37:57 INFO Uploading 1njg1q1in1q8bbqk91kx8z3pdmlqinh5-test-script (136B)15302026/10/09 17:37:57 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15312026/10/09 17:37:57 WARN Failed to register uploaded object key=1njg1q1in1q8bbqk91kx8z3pdmlqinh5.ls error="server returned 404: 404 page not found\n"15322026/10/09 17:37:57 WARN Failed to register uploaded object key=log/ph1ya1r3n0z3jzpqpl151m5lk6dq74a0-test-script.drv error="server returned 404: 404 page not found\n"15332026/10/09 17:37:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15342026/10/09 17:37:57 INFO Signed narinfos id=1 count=115352026/10/09 17:37:57 INFO Uploading 1 narinfos15362026/10/09 17:37:57 INFO Received complete push request method=POST path=/api/pushes/1/complete15372026/10/09 17:37:57 WARN Failed to register uploaded object key=1njg1q1in1q8bbqk91kx8z3pdmlqinh5.narinfo error="server returned 404: 404 page not found\n"1538--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.67s)1539=== CONT TestService_NativeMTLS15402026/10/09 17:37:57 INFO Completed push id=1 objects=4 duration=11.680423ms15412026/10/09 17:37:57 INFO Upload complete. (97ms)1542=== NAME TestClientWithDependencies1543 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1578189084/001/store) requires matching store prefix1544--- PASS: TestClientWithDependencies (0.88s)1545=== CONT TestMetricsInventory1546--- PASS: TestService_ReadScope_PublicByDefault (0.62s)1547=== CONT TestClientCADerivations15482026/10/09 17:37:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures15492026/10/09 17:37:57 INFO Garbage collection started15502026/10/09 17:37:57 INFO Aborted multipart uploads count=0 kept=01551--- PASS: TestService_healthCheckHandler (0.67s)1552=== CONT TestService_AuthMiddleware15532026/10/09 17:37:57 INFO Received cleanup request method=DELETE path=/api/pending_closures15542026/10/09 17:37:57 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket75/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""15552026/10/09 17:37:57 INFO Aborted multipart uploads count=0 kept=115562026/10/09 17:37:57 INFO Received cleanup request method=DELETE path=/api/pending_closures15572026/10/09 17:37:57 INFO Aborted multipart uploads count=1 kept=015582026/10/09 17:37:57 WARN Force mode enabled - objects will be deleted immediately without grace period1559--- PASS: TestMultipartCleanup (0.76s)1560=== CONT TestCacheConfigHandler1561=== RUN TestCacheConfigHandler/full_config,_no_issuer1562=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1563=== RUN TestCacheConfigHandler/no_cache_url_configured1564=== PAUSE TestCacheConfigHandler/no_cache_url_configured1565=== RUN TestCacheConfigHandler/no_signing_keys1566=== PAUSE TestCacheConfigHandler/no_signing_keys1567=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1568=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1569=== CONT TestProxyWriteTimeout/narinfo1570=== CONT TestProxyWriteTimeout/unknown_size1571=== CONT TestProxyWriteTimeout/10_GiB_nar1572=== CONT TestProxyWriteTimeout/1_GiB_nar1573--- PASS: TestProxyWriteTimeout (0.02s)1574 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1575 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1576 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1577 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1578=== CONT TestFarmLeadRoutes//api/farm/lead1579=== CONT TestFarmLeadRoutes//api/farm/lead/build-x861580--- PASS: TestFarmLeadRoutes (0.03s)1581 --- PASS: TestFarmLeadRoutes//api/farm/lead (0.00s)1582 --- PASS: TestFarmLeadRoutes//api/farm/lead/build-x86 (0.00s)1583=== CONT TestPendingClosureWriteTimeout/empty1584=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1585--- PASS: TestService_ReadAuthMiddleware (0.64s)1586=== CONT TestPendingClosureWriteTimeout/670k_objects1587=== CONT TestPendingClosureWriteTimeout/400_objects1588=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15892026/10/09 17:37:57 INFO Received uploads request method=POST path=/1590=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15912026/10/09 17:37:57 INFO Received complete multipart upload request method=POST path=/1592=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15932026/10/09 17:37:57 INFO Received request for more parts method=POST path=/1594=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15952026/10/09 17:37:57 INFO Received uploads request method=POST path=/1596--- PASS: TestUploadHandlersRejectInvalidKeys (0.11s)1597 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1598 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1599 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1600 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1601=== CONT TestIsValidUploadKey/narinfo1602=== CONT TestIsValidUploadKey/realisation_plus_in_output1603=== CONT TestIsValidUploadKey/unknown_type1604=== CONT TestIsValidUploadKey/build_log_home-manager_file1605=== CONT TestIsValidUploadKey/empty_key1606=== CONT TestIsValidUploadKey/realisation1607=== CONT TestIsValidUploadKey/absolute1608=== CONT TestIsValidUploadKey/build_log_equals1609=== CONT TestIsValidUploadKey/nar_plain1610=== CONT TestIsValidUploadKey/build_log_question_mark1611=== CONT TestIsValidUploadKey/traversal_nar1612=== CONT TestIsValidUploadKey/build_log_plus_in_name1613=== CONT TestIsValidUploadKey/build_log1614=== CONT TestIsValidUploadKey/traversal1615=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1616=== CONT TestIsValidUploadKey/nix-cache-info1617=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1618=== CONT TestIsValidUploadKey/index.html1619=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1620=== CONT TestIsValidUploadKey/nar_xz1621=== CONT TestIsValidUploadKey/nar_zst1622=== CONT TestIsValidUploadKey/listing1623--- PASS: TestIsValidUploadKey (0.37s)1624 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1625 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1626 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1627 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1628 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1629 --- PASS: TestIsValidUploadKey/realisation (0.00s)1630 --- PASS: TestIsValidUploadKey/absolute (0.00s)1631 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1632 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1633 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1634 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1635 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1636 --- PASS: TestIsValidUploadKey/build_log (0.00s)1637 --- PASS: TestIsValidUploadKey/traversal (0.00s)1638 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1639 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1640 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1641 --- PASS: TestIsValidUploadKey/index.html (0.00s)1642 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1643 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1644 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1645 --- PASS: TestIsValidUploadKey/listing (0.00s)1646=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16472026/10/09 17:37:57 INFO Received uploads request method=POST path=/16482026/10/09 17:37:57 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=016492026/10/09 17:37:57 INFO Vacuumed table table=pending_closures16502026/10/09 17:37:57 INFO Vacuumed table table=pending_objects16512026/10/09 17:37:57 INFO Vacuumed table table=multipart_uploads16522026/10/09 17:37:57 INFO Vacuumed table table=closures16532026/10/09 17:37:57 INFO Vacuumed table table=objects16542026/10/09 17:37:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16552026/10/09 17:37:57 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NWJiY2VjNjQtNzQ4Ni00NWNlLWE0YTAtODU0MDc1Y2I5MDU4LjRlY2E4Y2QwLTI0YzktNDNkYS1iNTI5LTM3YWY3OGZhMWRiOHgxNzkxNTY3NDc3MDM3MDQxODY5 parts=1016562026/10/09 17:37:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete1657--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.56s)1658=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16592026/10/09 17:37:57 INFO Received request for more parts method=POST path=/16602026/10/09 17:37:57 INFO Completed upload id=1 objects=2 duration=3.40755ms16612026/10/09 17:37:57 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000016622026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures16632026/10/09 17:37:57 INFO Starting cleanup of old closures method=DELETE path=/api/closures16642026/10/09 17:37:57 INFO lead: released remote=192.0.2.1:123416652026/10/09 17:37:57 INFO Aborted multipart uploads count=0 kept=016662026/10/09 17:37:57 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"16672026/10/09 17:37:57 WARN mTLS auth: bound subjects configured but subject DN unavailable16682026/10/09 17:37:57 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1669--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.47s)1670=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16712026/10/09 17:37:57 INFO Received complete multipart upload request method=POST path=/16722026/10/09 17:37:57 INFO lead: acquired remote=192.0.2.1:12341673=== RUN TestService_RequireScope_OIDC/builder_may_write1674=== PAUSE TestService_RequireScope_OIDC/builder_may_write1675=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1676=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1677=== RUN TestService_RequireScope_OIDC/ops_may_admin1678=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1679=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1680=== RUN TestService_RequireScope_OIDC/ops_may_not_write1681=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1682=== RUN TestService_RequireScope_OIDC/reader_may_not_write1683=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1684=== RUN TestService_RequireScope_OIDC/static_token_may_admin1685=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1686=== RUN TestService_RequireScope_OIDC/static_token_may_write1687=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1688=== RUN TestService_RequireScope_OIDC/reader_may_read1689=== PAUSE TestService_RequireScope_OIDC/reader_may_read1690=== RUN TestService_RequireScope_OIDC/writer_implies_read1691=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1692=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1693=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1694=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1695=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1696=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1697=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1698=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1699=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1700=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1701=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1702=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1703=== CONT TestIsValidCachePath/narinfo1704=== CONT TestIsValidCachePath/random_path1705=== CONT TestIsValidCachePath/short_hash1706=== CONT TestIsValidCachePath/wrong_extension1707=== CONT TestIsValidCachePath/leading_slash1708=== CONT TestIsValidCachePath/empty1709=== CONT TestIsValidCachePath/invalid_char_e1710=== CONT TestIsValidCachePath/invalid_char_u1711=== CONT TestIsValidCachePath/traversal_in_middle1712=== CONT TestIsValidCachePath/nar_uncompressed1713=== CONT TestIsValidCachePath/nix-cache-info1714=== CONT TestIsValidCachePath/index.html1715=== CONT TestIsValidCachePath/realisation1716=== CONT TestIsValidCachePath/traversal_parent1717=== CONT TestIsValidCachePath/log1718=== CONT TestIsValidCachePath/ls1719=== CONT TestIsValidCachePath/nar_xz1720=== CONT TestIsValidCachePath/nar_bz21721=== CONT TestIsValidCachePath/nar_zst1722=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1723=== CONT TestPush_RejectsBadRequests/bad_root1724--- PASS: TestIsValidCachePath (0.00s)1725 --- PASS: TestIsValidCachePath/narinfo (0.00s)1726 --- PASS: TestIsValidCachePath/random_path (0.00s)1727 --- PASS: TestIsValidCachePath/short_hash (0.00s)1728 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1729 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1730 --- PASS: TestIsValidCachePath/empty (0.00s)1731 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1732 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1733 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1734 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1735 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1736 --- PASS: TestIsValidCachePath/index.html (0.00s)1737 --- PASS: TestIsValidCachePath/realisation (0.00s)1738 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1739 --- PASS: TestIsValidCachePath/log (0.00s)1740 --- PASS: TestIsValidCachePath/ls (0.00s)1741 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1742 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1743 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1744 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)17452026/10/09 17:37:57 INFO Received push request method=POST path=/api/pushes1746=== CONT TestPush_RejectsBadRequests/no_roots17472026/10/09 17:37:57 INFO Received push request method=POST path=/api/pushes1748=== CONT TestPush_RejectsBadRequests/root_not_in_objects17492026/10/09 17:37:57 INFO Received push request method=POST path=/api/pushes1750=== CONT TestPush_RejectsBadRequests/no_objects17512026/10/09 17:37:57 INFO Received push request method=POST path=/api/pushes1752=== CONT TestParseSingleRange/none1753=== CONT TestParseSingleRange/open-ended1754=== CONT TestParseSingleRange/start_far_past_EOF1755=== CONT TestParseSingleRange/start_past_EOF1756=== CONT TestParseSingleRange/single_byte1757=== CONT TestParseSingleRange/suffix_exceeds_size1758=== CONT TestParseSingleRange/suffix1759--- PASS: TestPush_RejectsBadRequests (1.89s)1760 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1761 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1762 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1763 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1764=== CONT TestParseSingleRange/end_clamped_to_size1765=== CONT TestParseSingleRange/malformed_both_empty1766=== CONT TestParseSingleRange/malformed_end_before_start1767=== CONT TestParseSingleRange/closed1768=== CONT TestParseSingleRange/multi-range_ignored1769=== CONT TestParseSingleRange/unknown_unit1770=== CONT TestParseSingleRange/malformed_no_dash1771=== CONT TestGCEndsOnShutdown/before_the_run1772--- PASS: TestParseSingleRange (0.00s)1773 --- PASS: TestParseSingleRange/none (0.00s)1774 --- PASS: TestParseSingleRange/open-ended (0.00s)1775 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1776 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1777 --- PASS: TestParseSingleRange/single_byte (0.00s)1778 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1779 --- PASS: TestParseSingleRange/suffix (0.00s)1780 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1781 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1782 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1783 --- PASS: TestParseSingleRange/closed (0.00s)1784 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1785 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1786 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1787=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1788=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1789=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1790=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1791=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1792=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1793=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1794=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1795=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark17962026/10/09 17:37:57 INFO Received push request method=POST path=/api/pushes1797=== NAME TestClientIntegration1798 client_integration_test.go:286: Created store path: /build/TestClientIntegration3207275977/002/store/pw2na2cknix81g2w8viakw6iv4q63r3m-test-file.txt1799=== NAME TestNARDeduplicationMetadataUploadBug1800 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug3134996498/001/store/qalbhlcciwhsc4qsmbh6yy5nqaalh5h3-file1.txt18012026/10/09 17:37:57 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=018022026/10/09 17:37:57 INFO Vacuumed table table=pending_closures18032026/10/09 17:37:57 INFO Vacuumed table table=pending_objects18042026/10/09 17:37:57 INFO Received complete push request method=POST path=/api/pushes/1/complete18052026/10/09 17:37:57 INFO Vacuumed table table=multipart_uploads18062026/10/09 17:37:57 INFO Completed push id=1 objects=4 duration=8.626696ms18072026/10/09 17:37:57 INFO Vacuumed table table=closures18082026/10/09 17:37:57 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18092026/10/09 17:37:57 INFO Vacuumed table table=objects18102026/10/09 17:37:57 INFO Completed upload id=2 objects=2 duration=3.259169ms1811--- PASS: TestMetricsCommit (0.44s)1812=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1813--- PASS: TestCacheStatsHandler (0.44s)1814=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale18152026/10/09 17:37:57 WARN mTLS auth: subject not in bound subjects subject="CN=reader"18162026/10/09 17:37:57 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1817--- PASS: TestService_NativeMTLS (0.39s)1818=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18192026/10/09 17:37:57 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001820--- PASS: TestService_createPendingClosureHandler (1.17s)1821=== CONT TestResolveDBConnectionString/flag_wins1822=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1823=== CONT TestResolveDBConnectionString/nothing_configured1824=== CONT TestResolveDBConnectionString/missing_file_is_an_error1825=== CONT TestResolveDBConnectionString/file_when_flag_empty1826=== CONT TestServerTLSConfig/no_client_CA1827=== CONT TestServerTLSConfig/not_a_PEM_file1828--- PASS: TestResolveDBConnectionString (0.00s)1829 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1830 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1831 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1832 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1833 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1834=== CONT TestServerTLSConfig/missing_CA_file1835--- PASS: TestServerTLSConfig (0.00s)1836 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1837 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1838 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1839=== CONT TestClientErrorHandling/InvalidStorePath18402026/10/09 17:37:57 INFO Received push request method=POST path=/api/pushes18412026/10/09 17:37:57 INFO Received push request method=POST path=/api/pushes18422026/10/09 17:37:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18432026/10/09 17:37:57 INFO Uploading pw2na2cknix81g2w8viakw6iv4q63r3m-test-file.txt (152B)18442026/10/09 17:37:57 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18452026/10/09 17:37:57 INFO Uploading qalbhlcciwhsc4qsmbh6yy5nqaalh5h3-file1.txt (160B)18462026/10/09 17:37:57 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18472026/10/09 17:37:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18482026/10/09 17:37:57 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"18492026/10/09 17:37:57 WARN Failed to register uploaded object key=pw2na2cknix81g2w8viakw6iv4q63r3m.ls error="server returned 404: 404 page not found\n"18502026/10/09 17:37:57 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18512026/10/09 17:37:57 WARN Failed to register uploaded object key=qalbhlcciwhsc4qsmbh6yy5nqaalh5h3.ls error="server returned 404: 404 page not found\n"18522026/10/09 17:37:57 INFO Signed narinfos id=1 count=118532026/10/09 17:37:57 INFO Uploading 1 narinfos18542026/10/09 17:37:57 INFO Signed narinfos id=1 count=118552026/10/09 17:37:57 INFO Uploading 1 narinfos1856--- PASS: TestMetricsInventory (0.43s)1857=== CONT TestClientErrorHandling/ServerNotAvailable18582026/10/09 17:37:57 INFO Received complete push request method=POST path=/api/pushes/1/complete18592026/10/09 17:37:57 WARN Failed to register uploaded object key=pw2na2cknix81g2w8viakw6iv4q63r3m.narinfo error="server returned 404: 404 page not found\n"18602026/10/09 17:37:57 INFO Received complete push request method=POST path=/api/pushes/1/complete18612026/10/09 17:37:57 WARN Failed to register uploaded object key=qalbhlcciwhsc4qsmbh6yy5nqaalh5h3.narinfo error="server returned 404: 404 page not found\n"18622026/10/09 17:37:57 INFO Completed push id=1 objects=3 duration=9.178601ms18632026/10/09 17:37:57 INFO Completed push id=1 objects=3 duration=8.920099ms18642026/10/09 17:37:57 INFO Upload complete. (89ms)18652026/10/09 17:37:57 INFO Upload complete. (96ms)1866=== NAME TestNARDeduplicationMetadataUploadBug1867 metadata_upload_test.go:54: Retrieved narinfo from S3:1868 StorePath: /build/TestNARDeduplicationMetadataUploadBug3134996498/001/store/qalbhlcciwhsc4qsmbh6yy5nqaalh5h3-file1.txt1869 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1870 Compression: zstd1871 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1872 NarSize: 1601873 References: 1874 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf18752026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures1876 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1877 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1878 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}18792026/10/09 17:37:57 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1880--- PASS: TestService_AuthMiddleware (0.43s)1881=== CONT TestClientErrorHandling/InvalidAuthToken1882--- PASS: TestObjectStatsLargeCommit (1.77s)1883=== CONT TestCacheConfigHandler/full_config,_no_issuer1884=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1885=== CONT TestCacheConfigHandler/no_signing_keys1886=== CONT TestCacheConfigHandler/no_cache_url_configured1887--- PASS: TestCacheConfigHandler (0.00s)1888 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1889 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1890 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1891 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1892=== CONT TestService_RequireScope_OIDC/builder_may_write1893=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read18942026/10/09 17:37:57 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]1895=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1896=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1897=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1898=== CONT TestService_RequireScope_OIDC/writer_implies_read1899=== CONT TestService_RequireScope_OIDC/reader_may_read1900=== CONT TestService_RequireScope_OIDC/static_token_may_write1901=== CONT TestService_RequireScope_OIDC/static_token_may_admin1902=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1903=== CONT TestService_RequireScope_OIDC/reader_may_not_write1904=== CONT TestService_RequireScope_OIDC/ops_may_not_write1905=== CONT TestService_RequireScope_OIDC/ops_may_admin1906=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1907=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token1908--- PASS: TestService_RequireScope_OIDC (0.53s)1909 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1910 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1911 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1912 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1913 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1914 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1915 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1916 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1917 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1918 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1919 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1920 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1921 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1922 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1923=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1924=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19252026/10/09 17:37:57 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]1926=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19272026/10/09 17:37:57 WARN Authentication failed token_preview=eyJhbGciOi...FEGge-j0gg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]19282026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures1929--- PASS: TestService_AuthMiddleware_OIDC (0.45s)1930 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1931 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1932 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1933 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)19342026/10/09 17:37:57 INFO Aborted multipart uploads count=0 kept=01935=== NAME TestNARDeduplicationMetadataUploadBug1936 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug3134996498/001/store/mcrr6yl483j1dg2sm6pqvfnnkkgdwlf8-file2.txt19372026/10/09 17:37:57 INFO Received uploads request method=POST path=/api/pending_closures19382026/10/09 17:37:57 INFO Aborted multipart uploads count=0 kept=019392026/10/09 17:37:58 WARN Force mode enabled - objects will be deleted immediately without grace period19402026/10/09 17:37:58 INFO All 1 paths already cached1941=== NAME TestClientIntegration1942 client_integration_test.go:312: Retrieved narinfo from S3:1943 StorePath: /build/TestClientIntegration3207275977/002/store/pw2na2cknix81g2w8viakw6iv4q63r3m-test-file.txt1944 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1945 Compression: zstd1946 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11947 NarSize: 1521948 References: 1949 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11950 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1951 client_integration_test.go:313: Decompressed .ls content (64 bytes):1952 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1953 client_integration_test.go:316: Testing garbage collection...19542026/10/09 17:37:58 WARN Force mode enabled - objects will be deleted immediately without grace period19552026/10/09 17:37:58 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=019562026/10/09 17:37:58 INFO Vacuumed table table=pending_closures19572026/10/09 17:37:58 INFO Vacuumed table table=pending_objects19582026/10/09 17:37:58 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=019592026/10/09 17:37:58 INFO Vacuumed table table=multipart_uploads19602026/10/09 17:37:58 INFO Vacuumed table table=closures19612026/10/09 17:37:58 INFO Vacuumed table table=pending_closures19622026/10/09 17:37:58 INFO Vacuumed table table=objects19632026/10/09 17:37:58 INFO Vacuumed table table=pending_objects19642026/10/09 17:37:58 INFO Vacuumed table table=multipart_uploads19652026/10/09 17:37:58 INFO Vacuumed table table=closures19662026/10/09 17:37:58 INFO Vacuumed table table=objects19672026/10/09 17:37:58 INFO Aborted multipart uploads count=0 kept=01968=== NAME TestClientCADerivations1969 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations1590417255/001/store/f620kcjkp3d1xj1v66fig9qfzlc61q3c-ca-test19702026/10/09 17:37:58 WARN Force mode enabled - objects will be deleted immediately without grace period1971--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)1972 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.48s)1973 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.49s)19742026-10-09 17:37:58.067 UTC [1544] ERROR: canceling statement due to user request19752026-10-09 17:37:58.067 UTC [1544] CONTEXT: SQL statement "UPDATE object_stats s1976 SET object_count = s.object_count + n.n - o.n,1977 total_bytes = s.total_bytes + n.bytes - o.bytes1978 FROM (1979 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes1980 FROM new_rows WHERE deleted_at IS NULL1981 ) AS n,1982 (1983 SELECT count(*) AS n, coalesce(sum(size), 0) AS bytes1984 FROM old_rows WHERE deleted_at IS NULL1985 ) AS o1986 WHERE s.id AND (n.n <> o.n OR n.bytes <> o.bytes)"1987 PL/pgSQL function object_stats_update() line 3 at SQL statement19882026-10-09 17:37:58.067 UTC [1544] STATEMENT: -- name: MarkStaleObjects :execrows1989 WITH RECURSIVE ct AS (1990 SELECT timezone('UTC', now()) AS now1991 ),1992 closure_reach AS (1993 -- Start with all closure keys1994 SELECT o.key, o.refs1995 FROM objects o1996 INNER JOIN closures c ON o.key = c.key1997 UNION1998 -- Recursively add all referenced objects1999 SELECT o.key, o.refs2000 FROM objects o2001 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2002 ),2003 reachable_objects AS (2004 SELECT DISTINCT key FROM closure_reach2005 ),2006 stale_objects AS (2007 SELECT o.key2008 FROM objects AS o, ct2009 WHERE2010 NOT EXISTS (2011 SELECT 12012 FROM reachable_objects ro2013 WHERE ro.key = o.key2014 )2015 AND NOT EXISTS (2016 SELECT 12017 FROM pending_objects AS po2018 WHERE po.key = o.key2019 )2020 AND o.deleted_at IS NULL -- Only mark fresh objects2021 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2022 FOR UPDATE2023 )2024 UPDATE objects2025 SET2026 deleted_at = ct.now,2027 first_deleted_at = COALESCE(first_deleted_at, ct.now)2028 FROM stale_objects, ct2029 WHERE objects.key = stale_objects.key2030 20312026/10/09 17:37:58 INFO Starting cleanup of old closures method=DELETE path=/api/closures20322026/10/09 17:37:58 INFO Garbage collection started20332026/10/09 17:37:58 INFO Aborted multipart uploads count=0 kept=020342026/10/09 17:37:58 INFO Received push request method=POST path=/api/pushes2035=== NAME TestClientCADerivations2036 client_ca_test.go:139: Found 1 dependencies (including self)20372026/10/09 17:37:58 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/present20382026-10-09 17:37:58.093 UTC [139] LOG: checkpoints are occurring too frequently (12 seconds apart)20392026-10-09 17:37:58.093 UTC [139] HINT: Consider increasing the configuration parameter "max_wal_size".20402026-10-09 17:37:58.093 UTC [139] LOG: checkpoint starting: wal20412026/10/09 17:37:58 WARN Force mode enabled - objects will be deleted immediately without grace period20422026/10/09 17:37:58 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20432026/10/09 17:37:58 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign20442026/10/09 17:37:58 INFO Signed narinfos id=2 count=120452026/10/09 17:37:58 INFO Uploading 1 narinfos20462026/10/09 17:37:58 WARN Failed to register uploaded object key=mcrr6yl483j1dg2sm6pqvfnnkkgdwlf8.ls error="server returned 404: 404 page not found\n"20472026/10/09 17:37:58 INFO Received complete push request method=POST path=/api/pushes/2/complete20482026/10/09 17:37:58 WARN Failed to register uploaded object key=mcrr6yl483j1dg2sm6pqvfnnkkgdwlf8.narinfo error="server returned 404: 404 page not found\n"20492026/10/09 17:37:58 INFO Completed push id=2 objects=3 duration=2.034698ms20502026/10/09 17:37:58 INFO Upload complete. (70ms)2051=== NAME TestNARDeduplicationMetadataUploadBug2052 metadata_upload_test.go:76: Retrieved narinfo from S3:2053 StorePath: /build/TestNARDeduplicationMetadataUploadBug3134996498/001/store/mcrr6yl483j1dg2sm6pqvfnnkkgdwlf8-file2.txt2054 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2055 Compression: zstd2056 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2057 NarSize: 1602058 References: 2059 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2060 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2061 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2062 {"version":1,"root":{"type":"regular","size":44}}20632026/10/09 17:37:58 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=020642026/10/09 17:37:58 INFO Aborted multipart uploads count=0 kept=02065--- PASS: TestNARDeduplicationMetadataUploadBug (0.89s)20662026/10/09 17:37:58 INFO Vacuumed table table=pending_closures20672026/10/09 17:37:58 INFO Vacuumed table table=pending_objects20682026/10/09 17:37:58 INFO Vacuumed table table=multipart_uploads20692026/10/09 17:37:58 INFO Vacuumed table table=closures20702026/10/09 17:37:58 INFO Vacuumed table table=objects20712026/10/09 17:37:58 WARN Force mode enabled - objects will be deleted immediately without grace period20722026/10/09 17:37:58 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:37171/bucket99/?delete=\": context canceled"2073--- PASS: TestGCEndsOnShutdown (0.00s)2074 --- PASS: TestGCEndsOnShutdown/before_the_run (0.40s)2075 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.48s)2076 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.47s)20772026/10/09 17:37:58 WARN Request failed, retrying attempt=2 backoff=219.775552ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20782026/10/09 17:37:58 INFO Received push request method=POST path=/api/pushes20792026/10/09 17:37:58 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20802026/10/09 17:37:58 INFO Uploading f620kcjkp3d1xj1v66fig9qfzlc61q3c-ca-test (144B)20812026/10/09 17:37:58 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20822026/10/09 17:37:58 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"20832026/10/09 17:37:58 WARN Failed to register uploaded object key=log/gggv15vk4hy288xvj0yiaszih3lr2yfa-ca-test.drv error="server returned 404: 404 page not found\n"20842026/10/09 17:37:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20852026/10/09 17:37:58 WARN Failed to register uploaded object key=f620kcjkp3d1xj1v66fig9qfzlc61q3c.ls error="server returned 404: 404 page not found\n"20862026/10/09 17:37:58 INFO Signed narinfos id=1 count=120872026/10/09 17:37:58 INFO Uploading 1 narinfos20882026/10/09 17:37:58 INFO Received complete push request method=POST path=/api/pushes/1/complete20892026/10/09 17:37:58 WARN Failed to register uploaded object key=f620kcjkp3d1xj1v66fig9qfzlc61q3c.narinfo error="server returned 404: 404 page not found\n"20902026/10/09 17:37:58 INFO Completed push id=1 objects=4 duration=7.639228ms20912026/10/09 17:37:58 INFO Upload complete. (179ms)2092=== NAME TestClientCADerivations2093 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations1590417255/001/store/f620kcjkp3d1xj1v66fig9qfzlc61q3c-ca-test2094 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2095 Compression: zstd2096 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2097 NarSize: 1442098 References: 2099 Deriver: /build/TestClientCADerivations1590417255/001/store/gggv15vk4hy288xvj0yiaszih3lr2yfa-ca-test.drv2100 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2101 client_ca_test.go:185: Checking for realisation files in S3...2102 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2103 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache21042026/10/09 17:37:58 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2105--- PASS: TestUploadHandlersRejectOversizedBody (0.38s)2106 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)2107 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)2108 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.95s)21092026/10/09 17:37:58 WARN Request failed, retrying attempt=3 backoff=369.442325ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2110--- PASS: TestDeleteClosuresRacingPins (2.32s)2111=== NAME TestClientCADerivations2112 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features2113 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable2114 error: binary cache 's3://bucket92?endpoint=http://localhost:37171®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations1590417255/001/store'2115 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12116--- PASS: TestClientCADerivations (1.20s)2117--- PASS: TestPendingClosureWriteTimeout (0.10s)2118 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2119 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2120 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2121 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.16s)2122=== NAME TestOrphanedObjectsGCStressTest2123 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2124 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2125--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2126 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.91s)2127 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.94s)21282026/10/09 17:37:58 INFO lead: released remote=192.0.2.1:12342129--- PASS: TestLeadElectsOneAndHandsOver (2.89s)21302026/10/09 17:37:58 WARN Request failed, retrying attempt=4 backoff=794.770283ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2131=== NAME TestOrphanedObjectsGCStressTest2132 orphaned_objects_gc_test.go:503: Stress test completed successfully:2133 orphaned_objects_gc_test.go:504: - Active objects preserved: 202134 orphaned_objects_gc_test.go:505: - Objects deleted: 2102135 orphaned_objects_gc_test.go:506: - Total GC'd: 2102136--- PASS: TestOrphanedObjectsGCStressTest (2.95s)21372026/10/09 17:37:59 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:59 WARN Rate limiter enabled after throttle name=s3-test rate=521392026/10/09 17:37:59 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2140=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2141 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102142 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002143--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.87s)21442026/10/09 17:37:59 INFO Received create pin request method=POST path=/api/pins/myapp21452026/10/09 17:37:59 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1507603535/001/store/qhddpykw2h291raqifm41b75p6dnvjda-pinned-file.txt narinfo_key=qhddpykw2h291raqifm41b75p6dnvjda.narinfo21462026/10/09 17:37:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures21472026/10/09 17:37:59 INFO Garbage collection started21482026/10/09 17:37:59 INFO Aborted multipart uploads count=0 kept=021492026/10/09 17:37:59 WARN Force mode enabled - objects will be deleted immediately without grace period21502026/10/09 17:37:59 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=021512026/10/09 17:37:59 INFO Vacuumed table table=pending_closures21522026/10/09 17:37:59 INFO Vacuumed table table=pending_objects21532026/10/09 17:37:59 INFO Vacuumed table table=multipart_uploads21542026/10/09 17:37:59 INFO Vacuumed table table=closures21552026/10/09 17:37:59 INFO Vacuumed table table=objects21562026/10/09 17:37:59 WARN Request failed, retrying attempt=5 backoff=1.746497323s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2157--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.27s)21582026/10/09 17:38:00 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02159=== NAME TestClientIntegration2160 client_integration_test.go:323: Objects in database after GC:2161 client_integration_test.go:323: Successfully deleted all objects with GC --force2162--- PASS: TestClientIntegration (3.25s)2163--- PASS: TestConnectWaitsForAPeerMigration (5.47s)2164=== NAME TestPinProtectsFromGC2165 client_integration_test.go:840: Pin successfully protected closure from garbage collection2166--- PASS: TestPinProtectsFromGC (5.01s)21672026/10/09 17:38:01 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-config21682026/10/09 17:38:01 WARN Request failed, retrying attempt=2 backoff=199.099626ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21692026/10/09 17:38:01 WARN Request failed, retrying attempt=3 backoff=433.104063ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21702026/10/09 17:38:02 WARN Request failed, retrying attempt=4 backoff=790.606924ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21712026/10/09 17:38:02 WARN Request failed, retrying attempt=5 backoff=1.498013253s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21722026/10/09 17:38:03 INFO Aborted multipart uploads count=1 kept=021732026/10/09 17:38:03 INFO Received cleanup request method=DELETE path=/api/pending_closures21742026/10/09 17:38:03 INFO Aborted multipart uploads count=1 kept=02175--- PASS: TestPendingCleanupUsesOneCutoff (6.69s)21762026/10/09 17:38:04 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"21772026/10/09 17:38:04 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-config21782026/10/09 17:38:04 WARN Request failed, retrying attempt=2 backoff=208.128062ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21792026/10/09 17:38:04 WARN Request failed, retrying attempt=3 backoff=433.263616ms 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:38:05 WARN Request failed, retrying attempt=4 backoff=823.388681ms 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:38:05 WARN Request failed, retrying attempt=5 backoff=1.719790307s 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:38:07 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_closures21832026/10/09 17:38:07 WARN Request failed, retrying attempt=2 backoff=217.92532ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21842026/10/09 17:38:08 WARN Request failed, retrying attempt=3 backoff=414.652326ms 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:08 WARN Request failed, retrying attempt=4 backoff=791.674682ms 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:09 WARN Request failed, retrying attempt=5 backoff=1.507218869s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2187--- PASS: TestClientErrorHandling (0.00s)2188 --- PASS: TestClientErrorHandling/InvalidStorePath (0.40s)2189 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.56s)2190 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.98s)2191PASS21922026-10-09 17:38:10.984 UTC [132] LOG: received smart shutdown request21932026-10-09 17:38:10.987 UTC [132] LOG: background worker "logical replication launcher" (PID 144) exited with exit code 121942026-10-09 17:38:12.153 UTC [139] LOG: checkpoint complete: wrote 10914 buffers (66.6%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=13.086 s, sync=0.762 s, total=14.060 s; sync files=34382, longest=0.008 s, average=0.001 s; distance=533336 kB, estimate=533336 kB; lsn=0/2251FE40, redo lsn=0/2203C09021952026-10-09 17:38:12.158 UTC [139] LOG: shutting down21962026-10-09 17:38:12.158 UTC [139] LOG: checkpoint starting: shutdown immediate21972026-10-09 17:38:12.175 UTC [139] LOG: checkpoint complete: wrote 174 buffers (1.1%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s, sync=0.011 s, total=0.018 s; sync files=102, longest=0.001 s, average=0.001 s; distance=5007 kB, estimate=480503 kB; lsn=0/2251FEB8, redo lsn=0/2251FEB821982026-10-09 17:38:12.284 UTC [132] LOG: database system is shut down2199Running OIDC tests...2200=== RUN TestAudienceForIssuer2201=== PAUSE TestAudienceForIssuer2202=== RUN TestGlobMatch2203=== PAUSE TestGlobMatch2204=== RUN TestValidateToken_ValidToken2205=== PAUSE TestValidateToken_ValidToken2206=== RUN TestValidateToken_WrongAudience2207=== PAUSE TestValidateToken_WrongAudience2208=== RUN TestValidateToken_Expired2209=== PAUSE TestValidateToken_Expired2210=== RUN TestValidateToken_BoundClaimsMismatch2211=== PAUSE TestValidateToken_BoundClaimsMismatch2212=== RUN TestValidateToken_BoundSubjectMismatch2213=== PAUSE TestValidateToken_BoundSubjectMismatch2214=== RUN TestValidateToken_MultipleProviders2215=== PAUSE TestValidateToken_MultipleProviders2216=== RUN TestValidateToken_NoMatchingProvider2217=== PAUSE TestValidateToken_NoMatchingProvider2218=== RUN TestValidateToken_KubernetesServiceAccount2219=== PAUSE TestValidateToken_KubernetesServiceAccount2220=== RUN TestNewValidator_KubernetesRequiresCA2221=== PAUSE TestNewValidator_KubernetesRequiresCA2222=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2223=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2224=== RUN TestPins_ReservedForMatchingRule2225=== PAUSE TestPins_ReservedForMatchingRule2226=== RUN TestPins_TopLevelShorthand2227=== PAUSE TestPins_TopLevelShorthand2228=== RUN TestPins_ConfigValidation2229=== PAUSE TestPins_ConfigValidation2230=== RUN TestScopes_LegacyProviderDefaultsToWrite2231=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2232=== RUN TestScopes_Rules2233=== PAUSE TestScopes_Rules2234=== RUN TestScopes_ConfigValidation2235=== PAUSE TestScopes_ConfigValidation2236=== CONT TestAudienceForIssuer2237=== CONT TestPins_ConfigValidation2238--- PASS: TestAudienceForIssuer (0.00s)2239=== CONT TestValidateToken_NoMatchingProvider2240=== CONT TestValidateToken_KubernetesServiceAccount2241=== CONT TestScopes_Rules2242=== CONT TestScopes_ConfigValidation2243=== CONT TestScopes_LegacyProviderDefaultsToWrite2244=== CONT TestValidateToken_Expired2245--- PASS: TestScopes_ConfigValidation (0.00s)2246=== CONT TestValidateToken_MultipleProviders2247--- PASS: TestPins_ConfigValidation (0.00s)2248=== CONT TestValidateToken_BoundSubjectMismatch2249=== CONT TestValidateToken_BoundClaimsMismatch2250=== CONT TestPins_ReservedForMatchingRule2251=== CONT TestPins_TopLevelShorthand2252=== CONT TestValidateToken_ValidToken2253=== CONT TestValidateToken_WrongAudience2254=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2255=== CONT TestNewValidator_KubernetesRequiresCA2256=== CONT TestGlobMatch2257=== RUN TestGlobMatch/foo_foo2258=== PAUSE TestGlobMatch/foo_foo2259=== RUN TestGlobMatch/foo_bar2260=== PAUSE TestGlobMatch/foo_bar2261=== RUN TestGlobMatch/*_2262=== PAUSE TestGlobMatch/*_2263=== RUN TestGlobMatch/*_anything2264=== PAUSE TestGlobMatch/*_anything2265=== RUN TestGlobMatch/foo*_foo2266=== PAUSE TestGlobMatch/foo*_foo2267=== RUN TestGlobMatch/foo*_foobar2268=== PAUSE TestGlobMatch/foo*_foobar2269=== RUN TestGlobMatch/foo*_bar2270=== PAUSE TestGlobMatch/foo*_bar2271=== RUN TestGlobMatch/*bar_bar2272=== PAUSE TestGlobMatch/*bar_bar2273=== RUN TestGlobMatch/*bar_foobar2274=== PAUSE TestGlobMatch/*bar_foobar2275=== RUN TestGlobMatch/*bar_foo2276=== PAUSE TestGlobMatch/*bar_foo2277=== RUN TestGlobMatch/foo*bar_foobar2278=== PAUSE TestGlobMatch/foo*bar_foobar2279=== RUN TestGlobMatch/foo*bar_foo123bar2280=== PAUSE TestGlobMatch/foo*bar_foo123bar2281=== RUN TestGlobMatch/foo*bar_foobarbaz2282=== PAUSE TestGlobMatch/foo*bar_foobarbaz2283=== RUN TestGlobMatch/*/*_foo/bar2284=== PAUSE TestGlobMatch/*/*_foo/bar2285=== RUN TestGlobMatch/*/*_foo2286=== PAUSE TestGlobMatch/*/*_foo2287=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2288=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2289=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02290=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02291=== RUN TestGlobMatch/refs/*/main_refs/heads/main2292=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2293=== RUN TestGlobMatch/fo?_foo2294=== PAUSE TestGlobMatch/fo?_foo2295=== RUN TestGlobMatch/fo?_fo2296=== PAUSE TestGlobMatch/fo?_fo2297=== RUN TestGlobMatch/fo?_fooo2298=== PAUSE TestGlobMatch/fo?_fooo2299=== RUN TestGlobMatch/?oo_foo2300=== PAUSE TestGlobMatch/?oo_foo2301=== RUN TestGlobMatch/?oo_boo2302=== PAUSE TestGlobMatch/?oo_boo2303=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2304=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2305=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2306=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2307=== CONT TestGlobMatch/foo_foo2308=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2309=== CONT TestGlobMatch/?oo_boo2310=== CONT TestGlobMatch/?oo_foo2311=== CONT TestGlobMatch/fo?_fooo2312=== CONT TestGlobMatch/fo?_fo2313=== CONT TestGlobMatch/fo?_foo2314=== CONT TestGlobMatch/refs/*/main_refs/heads/main2315=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02316=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2317=== CONT TestGlobMatch/*/*_foo2318=== CONT TestGlobMatch/*/*_foo/bar2319=== CONT TestGlobMatch/foo*bar_foobarbaz2320=== CONT TestGlobMatch/foo*bar_foo123bar2321=== CONT TestGlobMatch/foo*bar_foobar2322=== CONT TestGlobMatch/foo*_foobar2323=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2324=== CONT TestGlobMatch/foo*_foo2325=== CONT TestGlobMatch/*_anything2326=== CONT TestGlobMatch/*_2327=== CONT TestGlobMatch/foo_bar2328=== CONT TestGlobMatch/*bar_foobar2329=== CONT TestGlobMatch/*bar_foo2330=== CONT TestGlobMatch/*bar_bar2331=== CONT TestGlobMatch/foo*_bar2332--- PASS: TestGlobMatch (0.00s)2333 --- PASS: TestGlobMatch/foo_foo (0.00s)2334 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2335 --- PASS: TestGlobMatch/?oo_boo (0.00s)2336 --- PASS: TestGlobMatch/?oo_foo (0.00s)2337 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2338 --- PASS: TestGlobMatch/fo?_fo (0.00s)2339 --- PASS: TestGlobMatch/fo?_foo (0.00s)2340 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2341 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2342 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2343 --- PASS: TestGlobMatch/*/*_foo (0.00s)2344 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2345 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2346 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2347 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2348 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2349 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2350 --- PASS: TestGlobMatch/foo*_foo (0.00s)2351 --- PASS: TestGlobMatch/*_anything (0.00s)2352 --- PASS: TestGlobMatch/*_ (0.00s)2353 --- PASS: TestGlobMatch/foo_bar (0.00s)2354 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2355 --- PASS: TestGlobMatch/*bar_foo (0.00s)2356 --- PASS: TestGlobMatch/*bar_bar (0.00s)2357 --- PASS: TestGlobMatch/foo*_bar (0.00s)23582026/10/09 17:38:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40323/oidc2359--- PASS: TestPins_TopLevelShorthand (0.07s)23602026/10/09 17:38:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35163/oidc2361--- PASS: TestPins_ReservedForMatchingRule (0.10s)23622026/10/09 17:38:14 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232363--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.10s)23642026/10/09 17:38:14 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:43895/oidc23652026/10/09 17:38:14 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:384292366--- PASS: TestValidateToken_NoMatchingProvider (0.14s)2367--- PASS: TestValidateToken_KubernetesServiceAccount (0.14s)23682026/10/09 17:38:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:32873/oidc2369--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.15s)23702026/10/09 17:38:14 http: TLS handshake error from 127.0.0.1:46702: remote error: tls: bad certificate2371--- PASS: TestNewValidator_KubernetesRequiresCA (0.15s)23722026/10/09 17:38:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40031/oidc2373--- PASS: TestValidateToken_BoundSubjectMismatch (0.18s)23742026/10/09 17:38:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36575/oidc2375--- PASS: TestValidateToken_Expired (0.23s)23762026/10/09 17:38:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39855/oidc23772026/10/09 17:38:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45437/oidc2378--- PASS: TestValidateToken_ValidToken (0.25s)2379--- PASS: TestValidateToken_WrongAudience (0.25s)23802026/10/09 17:38:14 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:39885/oidc23812026/10/09 17:38:14 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:36529/oidc2382--- PASS: TestValidateToken_MultipleProviders (0.29s)23832026/10/09 17:38:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42673/oidc2384--- PASS: TestValidateToken_BoundClaimsMismatch (0.34s)23852026/10/09 17:38:14 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35301/oidc2386--- PASS: TestScopes_Rules (0.35s)2387PASS2388Running hook tests...2389=== RUN TestSendPathsEmpty2390=== PAUSE TestSendPathsEmpty2391=== RUN TestQueueEnqueueAndFetch2392=== PAUSE TestQueueEnqueueAndFetch2393=== RUN TestQueueDeduplication2394=== PAUSE TestQueueDeduplication2395=== RUN TestQueueRemove2396=== PAUSE TestQueueRemove2397=== RUN TestQueueFetchBatchLimit2398=== PAUSE TestQueueFetchBatchLimit2399=== RUN TestQueueRetryMovesToBack2400=== PAUSE TestQueueRetryMovesToBack2401=== RUN TestQueueFetchRemoveLifecycle2402=== PAUSE TestQueueFetchRemoveLifecycle2403=== RUN TestQueueConcurrentWriters2404=== PAUSE TestQueueConcurrentWriters2405=== RUN TestQueueRemoveLargeClosure2406=== PAUSE TestQueueRemoveLargeClosure2407=== RUN TestServerClientIntegration2408--- PASS: TestServerClientIntegration (0.00s)2409=== RUN TestServerQueueError24102026/10/09 17:38:14 ERROR Failed to queue paths error="permission denied" count=12411--- PASS: TestServerQueueError (0.00s)2412=== RUN TestGetListenerSocketActivation2413 server_test.go:219: === RUN TestGetListenerSocketActivation2414 --- PASS: TestGetListenerSocketActivation (0.00s)2415 PASS2416 2417--- PASS: TestGetListenerSocketActivation (0.01s)2418=== RUN TestDrainIsolatesPoisonPath2419=== PAUSE TestDrainIsolatesPoisonPath2420=== RUN TestRunNotBlockedByPoisonHead2421=== PAUSE TestRunNotBlockedByPoisonHead2422=== RUN TestDrainGivesUpWhenServerDown2423=== PAUSE TestDrainGivesUpWhenServerDown2424=== RUN TestFailedPathPrunedByLaterClosure2425=== PAUSE TestFailedPathPrunedByLaterClosure2426=== RUN TestWorkerUploadsAndRemoves2427=== PAUSE TestWorkerUploadsAndRemoves2428=== RUN TestWorkerSkipsGCdPaths2429=== PAUSE TestWorkerSkipsGCdPaths2430=== RUN TestWorkerPrunesClosureDeps2431=== PAUSE TestWorkerPrunesClosureDeps2432=== RUN TestDrainTimeout2433=== PAUSE TestDrainTimeout2434=== CONT TestSendPathsEmpty2435--- PASS: TestSendPathsEmpty (0.00s)2436=== CONT TestWorkerPrunesClosureDeps2437=== CONT TestFailedPathPrunedByLaterClosure2438=== CONT TestQueueRetryMovesToBack2439=== CONT TestDrainTimeout2440=== CONT TestQueueFetchBatchLimit2441=== CONT TestQueueRemove2442=== CONT TestQueueDeduplication2443=== CONT TestQueueFetchRemoveLifecycle2444=== CONT TestQueueEnqueueAndFetch2445=== CONT TestDrainGivesUpWhenServerDown2446=== CONT TestRunNotBlockedByPoisonHead2447=== CONT TestWorkerSkipsGCdPaths2448=== CONT TestDrainIsolatesPoisonPath2449=== CONT TestQueueRemoveLargeClosure2450=== CONT TestQueueConcurrentWriters2451=== CONT TestWorkerUploadsAndRemoves24522026/10/09 17:38:14 INFO Upload queue status pending=224532026/10/09 17:38:14 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1345279208/002/nonexistent24542026/10/09 17:38:14 INFO Uploading batch count=124552026/10/09 17:38:14 ERROR Upload failed error="upload failed" count=124562026/10/09 17:38:14 INFO Upload queue status pending=324572026/10/09 17:38:14 INFO Uploading batch count=124582026/10/09 17:38:14 ERROR Upload failed error="upload failed" count=124592026/10/09 17:38:14 INFO Upload queue status pending=22460--- PASS: TestQueueEnqueueAndFetch (0.02s)24612026/10/09 17:38:14 INFO Upload queue status pending=22462--- PASS: TestQueueRemove (0.02s)24632026/10/09 17:38:14 INFO Uploading batch count=124642026/10/09 17:38:14 INFO Uploading batch count=224652026/10/09 17:38:14 INFO Uploading batch count=12466--- PASS: TestQueueRetryMovesToBack (0.02s)24672026/10/09 17:38:14 INFO Uploading batch count=124682026/10/09 17:38:14 INFO Uploading batch count=224692026/10/09 17:38:14 INFO Uploading batch count=224702026/10/09 17:38:14 ERROR Upload failed error="upload failed" count=224712026/10/09 17:38:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown791386338/002/a2472--- PASS: TestQueueFetchRemoveLifecycle (0.02s)24732026/10/09 17:38:14 INFO Uploading batch count=124742026/10/09 17:38:14 INFO Uploading batch count=424752026/10/09 17:38:14 ERROR Upload failed error="upload failed" count=424762026/10/09 17:38:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown791386338/002/b24772026/10/09 17:38:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3653073807/002/bbb2478--- PASS: TestQueueFetchBatchLimit (0.02s)2479--- PASS: TestQueueDeduplication (0.02s)24802026/10/09 17:38:14 INFO Uploading batch count=224812026/10/09 17:38:14 ERROR Upload failed error="upload failed" count=224822026/10/09 17:38:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown791386338/002/c24832026/10/09 17:38:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown791386338/002/d24842026/10/09 17:38:14 INFO Uploading batch count=124852026/10/09 17:38:14 ERROR Upload failed error="upload failed" count=124862026/10/09 17:38:14 INFO Uploading batch count=22487--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24882026/10/09 17:38:14 ERROR Upload failed error="upload failed" count=224892026/10/09 17:38:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown791386338/002/e24902026/10/09 17:38:14 INFO Uploading batch count=124912026/10/09 17:38:14 ERROR Upload failed error="upload failed" count=124922026/10/09 17:38:14 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown791386338/002/f24932026/10/09 17:38:14 INFO Uploading batch count=124942026/10/09 17:38:14 ERROR Upload failed error="upload failed" count=124952026/10/09 17:38:14 ERROR Drain finished with paths left in queue remaining=1024962026/10/09 17:38:14 ERROR Drain finished with paths left in queue remaining=12497--- PASS: TestDrainIsolatesPoisonPath (0.02s)2498--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2499--- PASS: TestWorkerSkipsGCdPaths (0.04s)2500--- PASS: TestWorkerUploadsAndRemoves (0.04s)2501--- PASS: TestWorkerPrunesClosureDeps (0.04s)2502--- PASS: TestQueueRemoveLargeClosure (0.11s)2503--- PASS: TestQueueConcurrentWriters (0.21s)25042026/10/09 17:38:14 ERROR Upload failed error="context deadline exceeded" count=225052026/10/09 17:38:14 ERROR Drain finished with paths left in queue remaining=42506--- PASS: TestDrainTimeout (0.22s)25072026/10/09 17:38:15 INFO Uploading batch count=125082026/10/09 17:38:15 INFO Uploading batch count=125092026/10/09 17:38:15 INFO Uploading batch count=125102026/10/09 17:38:15 ERROR Upload failed error="upload failed" count=125112026/10/09 17:38:15 INFO Uploading batch count=125122026/10/09 17:38:15 ERROR Upload failed error="upload failed" count=125132026/10/09 17:38:15 INFO Uploading batch count=125142026/10/09 17:38:15 ERROR Upload failed error="upload failed" count=125152026/10/09 17:38:15 INFO Uploading batch count=125162026/10/09 17:38:15 ERROR Upload failed error="upload failed" count=125172026/10/09 17:38:15 ERROR Drain finished with paths left in queue remaining=12518--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2519PASS2520Running signing tests...2521=== RUN TestExternalSigner2522=== PAUSE TestExternalSigner2523=== RUN TestExternalSignerWrongPublicKey2524=== PAUSE TestExternalSignerWrongPublicKey2525=== RUN TestExternalSignerErrors2526=== PAUSE TestExternalSignerErrors2527=== RUN TestExternalSignerRestartsAfterCrash2528=== PAUSE TestExternalSignerRestartsAfterCrash2529=== RUN TestExternalSignerProgramErrorKeepsProcess2530=== PAUSE TestExternalSignerProgramErrorKeepsProcess2531=== RUN TestExternalSignerClose2532=== PAUSE TestExternalSignerClose2533=== RUN TestExternalSignerRejectsInvalidPublicKey2534=== PAUSE TestExternalSignerRejectsInvalidPublicKey2535=== RUN TestExternalSignerCancellation2536=== PAUSE TestExternalSignerCancellation2537=== RUN TestGenerateFingerprint2538=== PAUSE TestGenerateFingerprint2539=== RUN TestParseSigningKey2540=== PAUSE TestParseSigningKey2541=== RUN TestSign2542=== PAUSE TestSign2543=== RUN TestSignBatch2544=== PAUSE TestSignBatch2545=== RUN TestNilKeyPublicKey2546=== PAUSE TestNilKeyPublicKey2547=== RUN TestSignErrors2548=== PAUSE TestSignErrors2549=== CONT TestExternalSigner2550=== CONT TestExternalSignerCancellation2551=== CONT TestSignBatch2552=== CONT TestParseSigningKey2553=== RUN TestParseSigningKey/valid_32-byte_key2554=== CONT TestGenerateFingerprint2555=== RUN TestGenerateFingerprint/basic_with_references2556=== CONT TestExternalSignerProgramErrorKeepsProcess2557=== PAUSE TestGenerateFingerprint/basic_with_references2558=== RUN TestGenerateFingerprint/no_references2559=== PAUSE TestGenerateFingerprint/no_references2560=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2561=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2562=== CONT TestExternalSignerRejectsInvalidPublicKey2563=== RUN TestExternalSignerRejectsInvalidPublicKey/#002564=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002565=== CONT TestExternalSignerClose2566=== CONT TestSignErrors2567=== CONT TestExternalSignerErrors2568=== RUN TestExternalSignerErrors/invalid_JSON2569=== PAUSE TestExternalSignerErrors/invalid_JSON2570=== RUN TestExternalSignerErrors/wrong_id2571=== PAUSE TestExternalSignerErrors/wrong_id2572=== RUN TestExternalSignerErrors/missing_signatures2573=== PAUSE TestExternalSignerErrors/missing_signatures2574=== RUN TestExternalSignerErrors/null_signatures2575=== PAUSE TestExternalSignerErrors/null_signatures2576=== RUN TestExternalSignerErrors/missing_signature_name2577=== CONT TestExternalSignerRestartsAfterCrash2578=== CONT TestExternalSignerWrongPublicKey2579=== CONT TestNilKeyPublicKey2580=== CONT TestSign2581=== PAUSE TestExternalSignerErrors/missing_signature_name2582=== RUN TestExternalSignerErrors/wrong_signatures_shape2583=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2584=== RUN TestExternalSignerErrors/invalid_signature_base642585=== PAUSE TestExternalSignerErrors/invalid_signature_base642586=== RUN TestExternalSignerErrors/wrong_signature_length2587=== PAUSE TestExternalSignerErrors/wrong_signature_length2588--- PASS: TestNilKeyPublicKey (0.00s)2589=== RUN TestExternalSignerErrors/program_error2590=== PAUSE TestExternalSignerErrors/program_error2591=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2592=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2593=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2594=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2595=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2596=== RUN TestExternalSignerErrors/exit_at_startup2597=== PAUSE TestExternalSignerErrors/exit_at_startup2598=== RUN TestExternalSignerErrors/exit_on_request2599=== PAUSE TestParseSigningKey/valid_32-byte_key2600=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2601=== RUN TestGenerateFingerprint/invalid_nar_hash_length2602=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2603=== RUN TestGenerateFingerprint/invalid_store_path_prefix2604=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2605=== RUN TestGenerateFingerprint/invalid_reference_prefix2606=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2607=== CONT TestGenerateFingerprint/basic_with_references2608=== PAUSE TestExternalSignerErrors/exit_on_request2609=== RUN TestExternalSignerErrors/wrong_shape2610=== CONT TestGenerateFingerprint/invalid_reference_prefix2611=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2612=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2613=== CONT TestGenerateFingerprint/invalid_nar_hash_length2614=== CONT TestGenerateFingerprint/invalid_store_path_prefix2615=== PAUSE TestExternalSignerErrors/wrong_shape2616=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2617=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2618=== RUN TestParseSigningKey/no_colon2619=== PAUSE TestParseSigningKey/no_colon2620=== RUN TestParseSigningKey/empty_name2621=== PAUSE TestParseSigningKey/empty_name2622=== RUN TestParseSigningKey/invalid_base642623=== PAUSE TestParseSigningKey/invalid_base642624=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2625=== RUN TestSignErrors/nil_key2626=== PAUSE TestSignErrors/nil_key2627=== RUN TestSignErrors/nil_narinfo2628=== PAUSE TestSignErrors/nil_narinfo2629=== RUN TestSignErrors/invalid_narinfo2630=== PAUSE TestSignErrors/invalid_narinfo2631--- PASS: TestSign (0.00s)2632=== RUN TestSignErrors/canceled2633=== PAUSE TestSignErrors/canceled2634=== CONT TestSignErrors/nil_key2635=== RUN TestExternalSignerErrors/too_few_signatures2636=== PAUSE TestExternalSignerErrors/too_few_signatures2637=== RUN TestExternalSignerErrors/wrong_signature_name2638=== PAUSE TestExternalSignerErrors/wrong_signature_name2639=== RUN TestExternalSignerErrors/null2640=== CONT TestSignErrors/invalid_narinfo2641=== PAUSE TestExternalSignerErrors/null2642=== RUN TestExternalSignerErrors/unrequested_key2643=== PAUSE TestExternalSignerErrors/unrequested_key2644=== CONT TestGenerateFingerprint/no_references2645--- PASS: TestGenerateFingerprint (0.00s)2646 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2647 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2648 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2649 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2650 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2651 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2652 --- PASS: TestGenerateFingerprint/no_references (0.00s)2653=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2654=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2655=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2656=== CONT TestSignErrors/nil_narinfo2657=== CONT TestExternalSignerErrors/wrong_id2658=== CONT TestExternalSignerErrors/missing_signatures2659=== RUN TestParseSigningKey/wrong_length2660=== CONT TestSignErrors/canceled2661=== CONT TestExternalSignerRejectsInvalidPublicKey/#002662=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2663=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2664=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2665=== CONT TestExternalSignerErrors/invalid_JSON2666=== CONT TestExternalSignerErrors/unrequested_key2667=== CONT TestExternalSignerErrors/null2668=== CONT TestExternalSignerErrors/wrong_signature_name2669=== CONT TestExternalSignerErrors/too_few_signatures2670=== CONT TestExternalSignerErrors/wrong_shape2671=== CONT TestExternalSignerErrors/exit_on_request2672=== CONT TestExternalSignerErrors/exit_at_startup2673=== CONT TestExternalSignerErrors/program_error2674=== CONT TestExternalSignerErrors/wrong_signature_length2675=== CONT TestExternalSignerErrors/invalid_signature_base642676=== CONT TestExternalSignerErrors/wrong_signatures_shape2677--- PASS: TestSignBatch (0.00s)2678=== CONT TestExternalSignerErrors/null_signatures2679=== CONT TestExternalSignerErrors/missing_signature_name2680=== PAUSE TestParseSigningKey/wrong_length2681=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2682--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2683=== CONT TestParseSigningKey/valid_32-byte_key2684=== CONT TestParseSigningKey/empty_name2685=== CONT TestParseSigningKey/wrong_length2686=== CONT TestParseSigningKey/invalid_base642687=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2688=== CONT TestParseSigningKey/no_colon2689--- PASS: TestSignErrors (0.00s)2690 --- PASS: TestSignErrors/nil_key (0.00s)2691 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2692 --- PASS: TestSignErrors/nil_narinfo (0.00s)2693 --- PASS: TestSignErrors/canceled (0.00s)2694--- PASS: TestExternalSignerWrongPublicKey (0.00s)2695--- PASS: TestExternalSignerClose (0.01s)2696--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2697 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2698 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2699 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2700 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2701 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2702--- PASS: TestParseSigningKey (0.01s)2703 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2704 --- PASS: TestParseSigningKey/empty_name (0.00s)2705 --- PASS: TestParseSigningKey/wrong_length (0.00s)2706 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2707 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2708 --- PASS: TestParseSigningKey/no_colon (0.00s)2709--- PASS: TestExternalSigner (0.01s)2710--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2711--- PASS: TestExternalSignerErrors (0.00s)2712 --- PASS: TestExternalSignerErrors/wrong_id (0.00s)2713 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2714 --- PASS: TestExternalSignerErrors/too_few_signatures (0.00s)2715 --- PASS: TestExternalSignerErrors/null (0.01s)2716 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2717 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2718 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)2719 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2720 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)2721 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2722 --- PASS: TestExternalSignerErrors/program_error (0.01s)2723 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2724 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)2725 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2726 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2727 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2728--- PASS: TestExternalSignerCancellation (0.02s)2729PASS2730Running OpenBao signer tests...2731=== RUN TestSign2732=== PAUSE TestSign2733=== RUN TestSignErrors2734=== PAUSE TestSignErrors2735=== RUN TestServe2736=== PAUSE TestServe2737=== RUN TestServeRejectsGarbage2738=== PAUSE TestServeRejectsGarbage2739=== CONT TestSign2740=== CONT TestServe2741=== CONT TestSignErrors2742=== CONT TestServeRejectsGarbage2743=== RUN TestSignErrors/http_error2744=== PAUSE TestSignErrors/http_error2745=== RUN TestSignErrors/invalid_json2746=== PAUSE TestSignErrors/invalid_json2747=== RUN TestSignErrors/no_prefix2748--- PASS: TestServeRejectsGarbage (0.00s)2749=== PAUSE TestSignErrors/no_prefix2750=== RUN TestSignErrors/invalid_base642751=== PAUSE TestSignErrors/invalid_base642752=== CONT TestSignErrors/http_error2753=== CONT TestSignErrors/invalid_json2754=== CONT TestSignErrors/no_prefix2755--- PASS: TestServe (0.00s)2756=== CONT TestSignErrors/invalid_base642757--- PASS: TestSign (0.01s)2758--- PASS: TestSignErrors (0.00s)2759 --- PASS: TestSignErrors/http_error (0.01s)2760 --- PASS: TestSignErrors/invalid_base64 (0.00s)2761 --- PASS: TestSignErrors/invalid_json (0.01s)2762 --- PASS: TestSignErrors/no_prefix (0.01s)2763PASS