niks3-go-unit-tests
checks.aarch64-linux.go-unit-tests
· build #408
· 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.03s)23=== RUN TestDumpPathCaseHackCollision24--- PASS: TestDumpPathCaseHackCollision (0.00s)25=== RUN TestSupersededNARStillUploadsListing26=== PAUSE TestSupersededNARStillUploadsListing27=== RUN TestDumpPathMatchesNix28=== PAUSE TestDumpPathMatchesNix29=== RUN TestDumpPathSingleFile30=== PAUSE TestDumpPathSingleFile31=== RUN TestDumpPathWriterError32=== PAUSE TestDumpPathWriterError33=== RUN TestEncodeNixBase3234=== PAUSE TestEncodeNixBase3235=== RUN TestEncodeNixBase32WithRealHash36=== PAUSE TestEncodeNixBase32WithRealHash37=== RUN TestConvertHashToNix3238=== PAUSE TestConvertHashToNix3239=== RUN TestGetStorePathHash40=== PAUSE TestGetStorePathHash41=== RUN TestPathInfoHashCompatibility42=== PAUSE TestPathInfoHashCompatibility43=== RUN TestParsePathInfoJSON44=== PAUSE TestParsePathInfoJSON45=== RUN TestParsePathInfoJSONMultiplePaths46=== PAUSE TestParsePathInfoJSONMultiplePaths47=== RUN TestPathInfoCACompatibility48=== PAUSE TestPathInfoCACompatibility49=== RUN TestRateLimiterFeedback50=== PAUSE TestRateLimiterFeedback51=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess52=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess53=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer54=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer55=== RUN TestResolveStorePath56=== PAUSE TestResolveStorePath57=== RUN TestDoWithRetry_BodyReplayedViaGetBody58=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody59=== RUN TestRetryTimeoutOutlastsMaxRetries60=== PAUSE TestRetryTimeoutOutlastsMaxRetries61=== RUN TestDoWithRetry_FinalResponseBodyReadable62=== PAUSE TestDoWithRetry_FinalResponseBodyReadable63=== RUN TestShellSplit64=== PAUSE TestShellSplit65=== RUN TestShellSplitErrors66=== PAUSE TestShellSplitErrors67=== RUN TestStreamPushReportsEveryPath68=== PAUSE TestStreamPushReportsEveryPath69=== RUN TestStreamPushBatchesUnderLoad70=== PAUSE TestStreamPushBatchesUnderLoad71=== RUN TestStreamPushIsolatesFailures72=== PAUSE TestStreamPushIsolatesFailures73=== RUN TestStreamPushGivesUpOnDeadServer74=== PAUSE TestStreamPushGivesUpOnDeadServer75=== RUN TestStreamPushRequestLine76=== PAUSE TestStreamPushRequestLine77=== RUN TestStreamPushReportsSignatures78=== PAUSE TestStreamPushReportsSignatures79=== RUN TestStreamPushReportsSkippedPaths80=== PAUSE TestStreamPushReportsSkippedPaths81=== RUN TestClientSignaturesByStorePath82=== PAUSE TestClientSignaturesByStorePath83=== RUN TestStreamPushStopsWhenCanceled84=== PAUSE TestStreamPushStopsWhenCanceled85=== RUN TestSetClientTLS86=== PAUSE TestSetClientTLS87=== RUN TestSetClientTLSDoesNotMutateDefaultTransport88=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport89=== RUN TestSetClientTLSErrors90=== PAUSE TestSetClientTLSErrors91=== RUN TestStaticToken92=== PAUSE TestStaticToken93=== RUN TestFileTokenReadsAndCaches94=== PAUSE TestFileTokenReadsAndCaches95=== RUN TestFileTokenMissing96=== PAUSE TestFileTokenMissing97=== RUN TestFileTokenEmpty98=== PAUSE TestFileTokenEmpty99=== RUN TestScriptTokenNoExpiryRerunsEveryCall100=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall101=== RUN TestScriptTokenCachesUntilRefresh102=== PAUSE TestScriptTokenCachesUntilRefresh103=== RUN TestScriptTokenEmptyToken104=== PAUSE TestScriptTokenEmptyToken105=== RUN TestScriptTokenBadJSON106=== PAUSE TestScriptTokenBadJSON107=== RUN TestScriptTokenScriptFails108=== PAUSE TestScriptTokenScriptFails109=== RUN TestScriptTokenEmptyCommand110=== PAUSE TestScriptTokenEmptyCommand111=== CONT TestDoServerRequestAttachesToken112=== CONT TestScriptTokenBadJSON113=== CONT TestDoWithRetry_BodyReplayedViaGetBody114=== CONT TestScriptTokenEmptyToken115=== CONT TestScriptTokenCachesUntilRefresh116=== CONT TestScriptTokenNoExpiryRerunsEveryCall117=== CONT TestFileTokenEmpty118=== CONT TestScriptTokenEmptyCommand119--- PASS: TestScriptTokenEmptyCommand (0.00s)120=== CONT TestFileTokenMissing121=== CONT TestStreamPushRequestLine122=== CONT TestStreamPushReportsSignatures123=== CONT TestStreamPushGivesUpOnDeadServer124=== CONT TestFileTokenReadsAndCaches125=== CONT TestStreamPushIsolatesFailures126=== CONT TestStaticToken127=== CONT TestStreamPushBatchesUnderLoad128=== CONT TestSetClientTLSErrors129=== CONT TestStreamPushReportsEveryPath130=== CONT TestSetClientTLSDoesNotMutateDefaultTransport131=== CONT TestShellSplitErrors132=== CONT TestSetClientTLS133=== CONT TestShellSplit134=== CONT TestStreamPushStopsWhenCanceled135=== CONT TestDoWithRetry_FinalResponseBodyReadable136=== CONT TestClientSignaturesByStorePath137--- PASS: TestClientSignaturesByStorePath (0.00s)138=== CONT TestRetryTimeoutOutlastsMaxRetries139--- PASS: TestScriptTokenBadJSON (0.00s)140=== CONT TestStreamPushReportsSkippedPaths141--- PASS: TestShellSplit (0.00s)142=== CONT TestEncodeNixBase32143=== RUN TestEncodeNixBase32/test_string_hash144=== PAUSE TestEncodeNixBase32/test_string_hash145=== RUN TestEncodeNixBase32/empty_input146=== PAUSE TestEncodeNixBase32/empty_input147=== CONT TestPartSizeForNAR148=== RUN TestPartSizeForNAR/zero_stays_at_minimum149=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum150=== RUN TestPartSizeForNAR/small_stays_at_minimum151=== PAUSE TestPartSizeForNAR/small_stays_at_minimum152=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum153=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum154=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts155=== CONT TestDumpPathWriterError156--- PASS: TestFileTokenMissing (0.00s)157--- PASS: TestStaticToken (0.00s)158--- PASS: TestShellSplitErrors (0.00s)159=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts160=== RUN TestPartSizeForNAR/1_TiB161=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess162=== PAUSE TestPartSizeForNAR/1_TiB1632026/10/10 19:42:18 ERROR Upload failed error="bad path" count=31642026/10/10 19:42:18 WARN Rate limiter enabled after throttle name=server-test rate=51652026/10/10 19:42:18 ERROR Upload failed error=boom count=11662026/10/10 19:42:18 ERROR Upload failed error="connection refused" count=201672026/10/10 19:42:18 ERROR Server seems unavailable, giving up on batch untried=171682026/10/10 19:42:18 ERROR Upload failed error=boom count=1169=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer1702026/10/10 19:42:18 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:46597171--- PASS: TestStreamPushReportsSkippedPaths (0.00s)172--- PASS: TestStreamPushStopsWhenCanceled (0.00s)173=== CONT TestDumpPathSingleFile174=== CONT TestResolveStorePath1752026/10/10 19:42:18 WARN Rate limiter enabled after throttle name=server-test rate=51762026/10/10 19:42:18 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:38373177=== RUN TestPartSizeForNAR/5_TiB_S3_max_object1782026/10/10 19:42:18 WARN Rate limiter enabled after throttle name=server-test rate=5179=== CONT TestPathInfoCACompatibility180=== RUN TestPathInfoCACompatibility/null_ca_field181=== PAUSE TestPathInfoCACompatibility/null_ca_field182=== RUN TestPathInfoCACompatibility/old_string_format_-_text183=== CONT TestUploadMultipart_SupersededByPeer184=== CONT TestDumpPathMatchesNix185=== CONT TestRateLimiterFeedback186=== CONT TestSupersededNARStillUploadsListing187--- PASS: TestFileTokenEmpty (0.00s)188=== RUN TestSetClientTLSErrors/missing_cert_file189=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text190--- PASS: TestScriptTokenEmptyToken (0.00s)191--- PASS: TestFileTokenReadsAndCaches (0.00s)192--- PASS: TestStreamPushReportsSignatures (0.00s)193--- PASS: TestStreamPushReportsEveryPath (0.00s)194--- PASS: TestStreamPushIsolatesFailures (0.00s)195=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object196=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive197=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive198=== RUN TestUploadMultipart_SupersededByPeer/exists199=== RUN TestSupersededNARStillUploadsListing/small_NAR200=== CONT TestParsePathInfoJSONMultiplePaths201=== CONT TestCaseHackSuffix2022026/10/10 19:42:18 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:465972032026/10/10 19:42:18 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:35961204=== PAUSE TestSetClientTLSErrors/missing_cert_file2052026/10/10 19:42:18 WARN Rate limiter backed off name=server-test rate=5206=== RUN TestRateLimiterFeedback/429_enables_limiter207--- PASS: TestDoServerRequestAttachesToken (0.01s)208=== RUN TestPartSizeForNAR/capped_at_5_GiB209=== PAUSE TestPartSizeForNAR/capped_at_5_GiB210--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)211=== CONT TestParsePathInfoJSON2122026/10/10 19:42:18 WARN Rate limiter backed off name=server-test rate=5213=== RUN TestParsePathInfoJSON/Nix_format214=== CONT TestUploadMultipart_PartsInParallel2152026/10/10 19:42:18 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:38373216=== CONT TestPathInfoHashCompatibility217=== RUN TestPathInfoCACompatibility/new_structured_format_-_text218=== PAUSE TestSupersededNARStillUploadsListing/small_NAR219=== PAUSE TestUploadMultipart_SupersededByPeer/exists220=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths221=== CONT TestFilterOversizedClosures222=== RUN TestSetClientTLS/rejects_connection_without_client_cert223--- PASS: TestResolveStorePath (0.00s)224=== CONT TestGetStorePathHash225=== RUN TestGetStorePathHash/valid_store_path226=== PAUSE TestRateLimiterFeedback/429_enables_limiter227=== PAUSE TestParsePathInfoJSON/Nix_format228=== RUN TestSetClientTLSErrors/missing_key_file229=== RUN TestParsePathInfoJSON/Lix_format230=== CONT TestConvertHashToNix32231=== RUN TestConvertHashToNix32/SRI_format_to_Nix32232=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica233=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)234--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)235=== RUN TestRateLimiterFeedback/503_enables_limiter236--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)237--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)238--- PASS: TestScriptTokenCachesUntilRefresh (0.01s)239=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text240=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method241=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method242=== RUN TestUploadMultipart_SupersededByPeer/missing243=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths244=== RUN TestSupersededNARStillUploadsListing/dump_cut_short245=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths246=== PAUSE TestUploadMultipart_SupersededByPeer/missing247=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short248=== RUN TestFilterOversizedClosures/no_limit_keeps_everything249=== PAUSE TestGetStorePathHash/valid_store_path250=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails251=== PAUSE TestSetClientTLSErrors/missing_key_file252=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails253=== CONT TestEncodeNixBase32WithRealHash254--- PASS: TestEncodeNixBase32WithRealHash (0.00s)255=== CONT TestScriptTokenScriptFails2562026/10/10 19:42:18 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:46597257=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun258=== PAUSE TestParsePathInfoJSON/Lix_format259=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32260=== RUN TestGetStorePathHash/basename_without_hyphen_should_error261=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error262=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error263=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error264=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything265=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped266=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths267=== CONT TestRegisterUploadedObjectReusesConnections268=== CONT TestEncodeNixBase32/empty_input269=== CONT TestPartSizeForNAR/zero_stays_at_minimum270=== CONT TestPartSizeForNAR/5_TiB_S3_max_object271=== CONT TestPartSizeForNAR/1_TiB272=== CONT TestPartSizeForNAR/capped_at_5_GiB273=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts274=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum275=== CONT TestPartSizeForNAR/small_stays_at_minimum276=== CONT TestPathInfoCACompatibility/null_ca_field277=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)278=== RUN TestSetClientTLSErrors/missing_ca_file279=== CONT TestPathInfoCACompatibility/new_structured_format_-_text2802026/10/10 19:42:18 INFO Garbage collection started281=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive2822026/10/10 19:42:18 INFO Garbage collection started283=== CONT TestPathInfoCACompatibility/old_string_format_-_text284=== CONT TestUploadMultipart_SupersededByPeer/exists285=== CONT TestUploadMultipart_SupersededByPeer/missing2862026/10/10 19:42:18 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:46597287=== PAUSE TestSetClientTLSErrors/missing_ca_file288=== RUN TestSetClientTLSErrors/invalid_ca_file289=== PAUSE TestSetClientTLSErrors/invalid_ca_file290=== CONT TestSupersededNARStillUploadsListing/small_NAR291=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert292=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA293=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA294=== RUN TestSetClientTLS/preserves_debug_logging_transport295=== PAUSE TestSetClientTLS/preserves_debug_logging_transport296--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)297=== CONT TestEncodeNixBase32/test_string_hash298=== RUN TestParsePathInfoJSON/empty_input299=== RUN TestConvertHashToNix32/already_Nix32_format300=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error301=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3022026/10/10 19:42:18 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=0303=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method304=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon305=== PAUSE TestRateLimiterFeedback/503_enables_limiter306=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3072026/10/10 19:42:18 INFO Uploading abc-hello (1.0GB)308=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths309=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths310=== CONT TestSetClientTLSErrors/missing_cert_file311=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon312=== CONT TestSetClientTLSErrors/missing_ca_file313=== CONT TestSetClientTLS/rejects_connection_without_client_cert3142026/10/10 19:42:18 INFO Uploading abc-hello (1.0GB)315=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error316=== CONT TestSetClientTLSErrors/invalid_ca_file317=== CONT TestSetClientTLS/preserves_debug_logging_transport3182026/10/10 19:42:18 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:46597319--- PASS: TestEncodeNixBase32 (0.00s)320 --- PASS: TestEncodeNixBase32/empty_input (0.00s)321 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)322--- PASS: TestScriptTokenScriptFails (0.03s)323=== PAUSE TestConvertHashToNix32/already_Nix32_format324=== PAUSE TestParsePathInfoJSON/empty_input325=== RUN TestFilterOversizedClosures/all_closures_skipped326=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI327=== CONT TestSetClientTLSErrors/missing_key_file328=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter329=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3302026/10/10 19:42:18 WARN Garbage collection finished on another replica. Its statistics are not available here331=== RUN TestConvertHashToNix32/invalid_format332--- PASS: TestCaseHackSuffix (0.04s)333=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error334=== CONT TestGetStorePathHash/basename_without_hyphen_should_error335=== CONT TestGetStorePathHash/valid_store_path336=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error337=== PAUSE TestConvertHashToNix32/invalid_format338=== CONT TestConvertHashToNix32/SRI_format_to_Nix32339=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter340=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter341=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter342=== CONT TestRateLimiterFeedback/429_enables_limiter343=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter344=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter345=== PAUSE TestFilterOversizedClosures/all_closures_skipped346=== CONT TestFilterOversizedClosures/no_limit_keeps_everything347=== CONT TestRateLimiterFeedback/503_enables_limiter348--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)349 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)350 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.00s)351--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.03s)352--- PASS: TestDumpPathSingleFile (0.05s)353--- PASS: TestPartSizeForNAR (0.01s)354 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)355 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)356 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)357 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)358 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)359 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)360 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)361--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.04s)362=== CONT TestFilterOversizedClosures/all_closures_skipped3632026/10/10 19:42:18 WARN Rate limiter enabled after throttle name=server-test rate=5364=== RUN TestParsePathInfoJSON/whitespace_only3652026/10/10 19:42:18 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:33443366=== PAUSE TestParsePathInfoJSON/whitespace_only367=== RUN TestParsePathInfoJSON/invalid_JSON368=== PAUSE TestParsePathInfoJSON/invalid_JSON3692026/10/10 19:42:18 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=50370=== CONT TestParsePathInfoJSON/Nix_format371=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3722026/10/10 19:42:18 WARN Rate limiter backed off name=server-test rate=53732026/10/10 19:42:18 WARN Rate limiter enabled after throttle name=server-test rate=53742026/10/10 19:42:18 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:43751375--- PASS: TestParsePathInfoJSONMultiplePaths (0.04s)376 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)377 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)378--- PASS: TestPathInfoCACompatibility (0.01s)379 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)380 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)381 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)382 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)383 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)384--- PASS: TestGetStorePathHash (0.04s)385 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)386 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)387 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)388 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)389=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI390=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped391=== CONT TestConvertHashToNix32/invalid_format392=== CONT TestConvertHashToNix32/already_Nix32_format393=== CONT TestParsePathInfoJSON/whitespace_only394=== CONT TestParsePathInfoJSON/empty_input395=== CONT TestParsePathInfoJSON/invalid_JSON396=== CONT TestParsePathInfoJSON/Lix_format397--- PASS: TestSetClientTLSErrors (0.31s)398 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)399 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)400 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.01s)401 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)402--- PASS: TestStreamPushBatchesUnderLoad (0.32s)4032026/10/10 19:42:19 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=2000404=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha5124052026/10/10 19:42:19 WARN Rate limiter backed off name=server-test rate=5406=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha5124072026/10/10 19:42:19 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:33357/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:33357/api/uploads/complete408=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)4092026/10/10 19:42:19 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4102026/10/10 19:42:19 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:33357/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:33357/api/uploads/complete411=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha5124122026/10/10 19:42:19 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4132026/10/10 19:42:19 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:33357/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:33357/api/uploads/complete414--- PASS: TestFilterOversizedClosures (0.04s)415 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)416 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)417 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)4182026/10/10 19:42:19 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"419=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI420--- PASS: TestRateLimiterFeedback (0.05s)421 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)422 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)423 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)424 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.27s)4252026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:46597426=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon427--- PASS: TestConvertHashToNix32 (0.04s)428 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)429 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)430 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)431--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.32s)432--- PASS: TestParsePathInfoJSON (0.05s)433 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)434 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)435 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)436 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)437 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)438--- PASS: TestPathInfoHashCompatibility (0.31s)439 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)440 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)441 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)442 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)4432026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:465974442026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:465974452026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:465974462026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:465974472026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:465974482026/10/10 19:42:19 http: TLS handshake error from 127.0.0.1:35392: remote error: tls: bad certificate449--- PASS: TestSetClientTLS (0.05s)450 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.27s)451 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.27s)452 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.28s)4532026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:465974542026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:465974552026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:465974562026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:46597457--- PASS: TestRegisterUploadedObjectReusesConnections (0.29s)458--- PASS: TestStreamPushRequestLine (0.33s)4592026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:465974602026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:465974612026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:465974622026/10/10 19:42:19 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:46597463--- PASS: TestDumpPathWriterError (0.34s)464--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.34s)4652026/10/10 19:42:19 INFO Uploading abc-hello (1.0GB)4662026/10/10 19:42:19 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:46031/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:46031/part/2467--- PASS: TestDumpPathMatchesNix (0.37s)4682026/10/10 19:42:19 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:46031/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:46031/part/34692026/10/10 19:42:19 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"470--- PASS: TestSupersededNARStillUploadsListing (0.01s)471 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.27s)472 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.28s)473 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.82s)474--- PASS: TestUploadMultipart_PartsInParallel (0.89s)475--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)476PASS477Running server tests...478The files belonging to this database system will be owned by user "nixbld".479This user must also own the server process.480481The database cluster will be initialized with locale "C".482The default database encoding has accordingly been set to "SQL_ASCII".483The default text search configuration will be set to "english".484485Data page checksums are enabled.486487creating directory /build/postgres4249745775/data ... ok488creating subdirectories ... ok489selecting dynamic shared memory implementation ... posix490selecting default "max_connections" ... 100491selecting default "shared_buffers" ... 128MB492selecting default time zone ... UTC493creating configuration files ... ok494running bootstrap script ... ok495performing post-bootstrap initialization ... ok496syncing data to disk ... ok497498initdb: warning: enabling "trust" authentication for local connections499initdb: 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.500501Success. You can now start the database server using:502503 pg_ctl -D /build/postgres4249745775/data -l logfile start504505/build/postgres4249745775:5432 - no response5062026-10-10 19:42:20.639 UTC [127] LOG: starting PostgreSQL 18.6 on aarch64-unknown-linux-gnu, compiled by clang version 21.1.8, 64-bit5072026-10-10 19:42:20.640 UTC [127] LOG: listening on Unix socket "/build/postgres4249745775/.s.PGSQL.5432"5082026-10-10 19:42:20.644 UTC [134] LOG: database system was shut down at 2026-10-10 19:42:20 UTC5092026-10-10 19:42:20.647 UTC [127] LOG: database system is ready to accept connections510/build/postgres4249745775:5432 - accepting connections511=== RUN TestService_AuthMiddleware512=== PAUSE TestService_AuthMiddleware513=== RUN TestService_AuthMiddleware_MTLSProxyHeader514=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader515=== RUN TestService_AuthMiddleware_MTLSBoundSubjects516=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects517=== RUN TestService_ReadAuthMiddleware518=== PAUSE TestService_ReadAuthMiddleware519=== RUN TestService_AuthMiddleware_OIDC520=== PAUSE TestService_AuthMiddleware_OIDC521=== RUN TestService_RequireScope_OIDC522=== PAUSE TestService_RequireScope_OIDC523=== RUN TestService_ReadScope_PublicByDefault524=== PAUSE TestService_ReadScope_PublicByDefault525=== RUN TestCacheConfigHandler526=== PAUSE TestCacheConfigHandler527=== RUN TestCacheStatsHandler528=== PAUSE TestCacheStatsHandler529=== RUN TestClientCADerivations530=== PAUSE TestClientCADerivations531=== RUN TestClientErrorHandling532=== PAUSE TestClientErrorHandling533=== RUN TestClientIntegration534=== PAUSE TestClientIntegration535=== RUN TestClientMultipleUploads536=== PAUSE TestClientMultipleUploads537=== RUN TestClientWithDependencies538=== PAUSE TestClientWithDependencies539=== RUN TestClientSharedPathCommittedMidPush540=== PAUSE TestClientSharedPathCommittedMidPush541=== RUN TestPinProtectsFromGC542=== PAUSE TestPinProtectsFromGC543=== RUN TestClientPushesUseOnePush544=== PAUSE TestClientPushesUseOnePush545=== RUN TestClientFallsBackToClosures546=== PAUSE TestClientFallsBackToClosures547=== RUN TestDeleteClosuresRacingPins548=== PAUSE TestDeleteClosuresRacingPins549=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock550=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock551=== RUN TestResolveDBConnectionString552=== PAUSE TestResolveDBConnectionString553=== RUN TestConnectWaitsForAPeerMigration554=== PAUSE TestConnectWaitsForAPeerMigration555=== RUN TestLeadElectsOneAndHandsOver556=== PAUSE TestLeadElectsOneAndHandsOver557=== RUN TestLeadIncumbentWinsAfterRestart5582026/10/10 19:42:21 INFO lead: acquired remote=192.0.2.1:12345592026/10/10 19:42:21 INFO lead: released remote=192.0.2.1:12345602026/10/10 19:42:21 INFO lead: acquired remote=192.0.2.1:12345612026/10/10 19:42:22 INFO lead: released remote=192.0.2.1:1234562--- PASS: TestLeadIncumbentWinsAfterRestart (1.88s)563=== RUN TestLeadIncumbentAnnouncesAtOnce564=== PAUSE TestLeadIncumbentAnnouncesAtOnce565=== RUN TestLeadEndsOnShutdown566=== PAUSE TestLeadEndsOnShutdown567=== RUN TestLeadEndsWhenItsConnectionHangs5682026/10/10 19:42:22 INFO lead: acquired remote=192.0.2.1:12345692026-10-10 19:42:24.343 UTC [381] FATAL: terminating connection due to administrator command5702026/10/10 19:42:24 INFO lead: acquired remote=192.0.2.1:12345712026/10/10 19:42:25 WARN lead: lock connection lost error="timeout: context deadline exceeded"5722026/10/10 19:42:25 INFO lead: released remote=192.0.2.1:12345732026/10/10 19:42:25 INFO lead: released remote=192.0.2.1:1234574--- PASS: TestLeadEndsWhenItsConnectionHangs (3.12s)575=== RUN TestGCAdvisoryLockBlocksConcurrentRun576=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun577=== RUN TestGCBugBareHashReferences578=== PAUSE TestGCBugBareHashReferences579=== RUN TestGCMetrics580=== PAUSE TestGCMetrics581=== RUN TestPushDedupSurvivesConcurrentGC582=== PAUSE TestPushDedupSurvivesConcurrentGC583=== RUN TestDeduplicatedObjectsRecordedAsPending584=== PAUSE TestDeduplicatedObjectsRecordedAsPending585=== RUN TestGCSweepSkipsPendingObjects586=== PAUSE TestGCSweepSkipsPendingObjects587=== RUN TestTombstonedObjectOfferedWithoutWaiting588=== PAUSE TestTombstonedObjectOfferedWithoutWaiting589=== RUN TestGCSweepDeliversEachKeyOnce590=== PAUSE TestGCSweepDeliversEachKeyOnce591=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection592=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection593=== RUN TestForceGCDuringPushOffersSweptObject594=== PAUSE TestForceGCDuringPushOffersSweptObject595=== RUN TestFailedS3DeleteKeepsTombstone596=== PAUSE TestFailedS3DeleteKeepsTombstone597=== RUN TestSweepSkipsRowsLockedByPush598=== PAUSE TestSweepSkipsRowsLockedByPush599=== RUN TestRegisterCompletedObjectNeedsPendingRow600=== PAUSE TestRegisterCompletedObjectNeedsPendingRow601=== RUN TestGetExistingObjectsLocksRows602=== PAUSE TestGetExistingObjectsLocksRows603=== RUN TestSweepRechecksPendingAfterLocking604=== PAUSE TestSweepRechecksPendingAfterLocking605=== RUN TestPushWaitsForSweepHoldingRow606=== PAUSE TestPushWaitsForSweepHoldingRow607=== RUN TestCommitRacingPendingCleanupKeepsObjects608=== PAUSE TestCommitRacingPendingCleanupKeepsObjects609=== RUN TestGCEndsOnShutdown610=== PAUSE TestGCEndsOnShutdown611=== RUN TestGCTaskStore_StartNew612=== PAUSE TestGCTaskStore_StartNew613=== RUN TestGCTaskStore_DeduplicateSameParams614=== PAUSE TestGCTaskStore_DeduplicateSameParams615=== RUN TestGCTaskStore_ConflictDifferentParams616=== PAUSE TestGCTaskStore_ConflictDifferentParams617=== RUN TestGCTaskStore_GetEmpty618=== PAUSE TestGCTaskStore_GetEmpty619=== RUN TestGCTaskStore_GetReturnsLatest620=== PAUSE TestGCTaskStore_GetReturnsLatest621=== RUN TestGCTaskStore_CompletedAllowsNewTask622=== PAUSE TestGCTaskStore_CompletedAllowsNewTask623=== RUN TestGCTaskStore_PhaseUpdates624=== PAUSE TestGCTaskStore_PhaseUpdates625=== RUN TestGCTaskStore_Fail626=== PAUSE TestGCTaskStore_Fail627=== RUN TestGracefulShutdownDrainsInflight628=== PAUSE TestGracefulShutdownDrainsInflight629=== RUN TestService_healthCheckHandler630=== PAUSE TestService_healthCheckHandler631=== RUN TestService_readinessHandler632=== PAUSE TestService_readinessHandler633=== RUN TestGenerateLandingPage634=== PAUSE TestGenerateLandingPage635=== RUN TestCacheConfigHandlerMaxNarSize636=== PAUSE TestCacheConfigHandlerMaxNarSize637=== RUN TestCreatePendingClosureRejectsOversizedNAR638=== PAUSE TestCreatePendingClosureRejectsOversizedNAR639=== RUN TestNARDeduplicationMetadataUploadBug640=== PAUSE TestNARDeduplicationMetadataUploadBug641=== RUN TestMetricsInventory642=== PAUSE TestMetricsInventory643=== RUN TestMetricsCommit644=== PAUSE TestMetricsCommit645=== RUN TestService_NativeMTLS646=== PAUSE TestService_NativeMTLS647=== RUN TestServerTLSConfig648=== PAUSE TestServerTLSConfig649=== RUN TestMultipartCleanup650=== PAUSE TestMultipartCleanup651=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded652=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded653=== RUN TestPendingCleanupUsesOneCutoff654=== PAUSE TestPendingCleanupUsesOneCutoff655=== RUN TestObjectStatsTrigger656=== PAUSE TestObjectStatsTrigger657=== RUN TestObjectStatsLargeCommit658=== PAUSE TestObjectStatsLargeCommit659=== RUN TestOrphanedObjectsGC660=== PAUSE TestOrphanedObjectsGC661=== RUN TestOrphanedObjectsGCStressTest662=== PAUSE TestOrphanedObjectsGCStressTest663=== RUN TestCreatePin_ReservedPins664=== PAUSE TestCreatePin_ReservedPins665=== RUN TestPresentReportsOnlyClosureRoots666=== PAUSE TestPresentReportsOnlyClosureRoots667=== RUN TestPresentRefreshesOnlyStaleClosures668=== PAUSE TestPresentRefreshesOnlyStaleClosures669=== RUN TestPresentNotReportedWhileGCDeletesClosure670=== PAUSE TestPresentNotReportedWhileGCDeletesClosure671=== RUN TestParseSingleRange672=== PAUSE TestParseSingleRange673=== RUN TestProxyHeadersOnlyTrustedOnSocket6742026/10/10 19:42:26 INFO Starting HTTP server address=127.0.0.1:440616752026/10/10 19:42:26 INFO Starting HTTP server address=proxy.sock6762026/10/10 19:42:26 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6772026/10/10 19:42:26 INFO Shutdown signal received, draining in-flight requests timeout=10s678--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.11s)679=== RUN TestIsValidCachePath680=== PAUSE TestIsValidCachePath681=== RUN TestReadProxyNarinfo682=== PAUSE TestReadProxyNarinfo683=== RUN TestReadProxyNarinfoAlreadyDecompressed684=== PAUSE TestReadProxyNarinfoAlreadyDecompressed685=== RUN TestReadProxyContentNegotiation686=== PAUSE TestReadProxyContentNegotiation687=== RUN TestReadProxyNarStreaming688=== PAUSE TestReadProxyNarStreaming689=== RUN TestReadProxy404690=== PAUSE TestReadProxy404691=== RUN TestReadProxyInvalidPath692=== PAUSE TestReadProxyInvalidPath693=== RUN TestReadProxyHead694=== PAUSE TestReadProxyHead695=== RUN TestReadProxyOutlastsServerWriteTimeout696=== PAUSE TestReadProxyOutlastsServerWriteTimeout697=== RUN TestReadProxyConditionalGet698=== PAUSE TestReadProxyConditionalGet699=== RUN TestReadProxyRootRedirectsToIndexHTML700=== PAUSE TestReadProxyRootRedirectsToIndexHTML701=== RUN TestReadProxyDisabled702=== PAUSE TestReadProxyDisabled703=== RUN TestReadRedirectNar704=== PAUSE TestReadRedirectNar705=== RUN TestReadRedirectKeepsNarinfoProxied706=== PAUSE TestReadRedirectKeepsNarinfoProxied707=== RUN TestReadProxyRangeRequest708=== PAUSE TestReadProxyRangeRequest709=== RUN TestReadRedirectUsesPublicS3URL710=== PAUSE TestReadRedirectUsesPublicS3URL711=== RUN TestPush_OverlappingRootsStoreOneRowPerKey712=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey713=== RUN TestPush_CompleteCommitsEveryRoot714=== PAUSE TestPush_CompleteCommitsEveryRoot715=== RUN TestPush_RepeatedRootCommitsOnce716=== PAUSE TestPush_RepeatedRootCommitsOnce717=== RUN TestPush_CompleteWaitsForCleanupOfThePush718=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush719=== RUN TestPush_RootsAreLockedInByteOrder720=== PAUSE TestPush_RootsAreLockedInByteOrder721=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit722=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit723=== RUN TestPush_RejectsBadRequests724=== PAUSE TestPush_RejectsBadRequests725=== RUN TestPush_SignsNarinfosOfItsPendingObjects726=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects727=== RUN TestRedundantMultipartUpload728=== PAUSE TestRedundantMultipartUpload729=== RUN TestCompleteMultipartUpload_ErrorButObjectExists730=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists731=== RUN TestCompletedNarNotReofferedAcrossClosures732=== PAUSE TestCompletedNarNotReofferedAcrossClosures733=== RUN TestPresignedUploadRegisteredBeforeCommit734=== PAUSE TestPresignedUploadRegisteredBeforeCommit735=== RUN TestService_Rustfstest736=== PAUSE TestService_Rustfstest737=== RUN TestParseSize738=== PAUSE TestParseSize739=== RUN TestSkippedUploadsHandler740=== PAUSE TestSkippedUploadsHandler741=== RUN TestSystemdListenerNotActivated742--- PASS: TestSystemdListenerNotActivated (0.00s)743=== RUN TestWatchdogBeatsWhenHealthy744--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)745=== RUN TestWatchdogSkipsWhenUnhealthy7462026/10/10 19:42:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/10/10 19:42:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7482026/10/10 19:42:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7492026/10/10 19:42:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7502026/10/10 19:42:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7512026/10/10 19:42:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7522026/10/10 19:42:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7532026/10/10 19:42:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7542026/10/10 19:42:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7552026/10/10 19:42:26 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"756--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)757=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle758=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle759=== RUN TestProxyWriteTimeout760=== PAUSE TestProxyWriteTimeout761=== RUN TestPendingClosureWriteTimeout762=== PAUSE TestPendingClosureWriteTimeout763=== RUN TestIsValidUploadKey764=== PAUSE TestIsValidUploadKey765=== RUN TestUploadHandlersRejectInvalidKeys766=== PAUSE TestUploadHandlersRejectInvalidKeys767=== RUN TestUploadHandlersRejectOversizedBody768=== PAUSE TestUploadHandlersRejectOversizedBody769=== RUN TestService_cleanupPendingClosuresHandler770=== PAUSE TestService_cleanupPendingClosuresHandler771=== RUN TestService_createPendingClosureHandler772=== PAUSE TestService_createPendingClosureHandler773=== RUN TestService_verifyS3Integrity774=== PAUSE TestService_verifyS3Integrity775=== RUN TestCompleteMultipartUnregistered776=== PAUSE TestCompleteMultipartUnregistered777=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT778=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT779=== CONT TestParseSize780=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit781=== CONT TestPush_RootsAreLockedInByteOrder782--- PASS: TestParseSize (0.00s)783=== CONT TestService_AuthMiddleware784=== CONT TestService_Rustfstest785=== CONT TestGCTaskStore_CompletedAllowsNewTask786--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)787=== CONT TestReadProxyHead788=== CONT TestPresentRefreshesOnlyStaleClosures789=== CONT TestCompletedNarNotReofferedAcrossClosures790=== CONT TestCompleteMultipartUpload_ErrorButObjectExists791=== CONT TestRedundantMultipartUpload792=== CONT TestPush_SignsNarinfosOfItsPendingObjects793=== CONT TestPush_RejectsBadRequests794=== CONT TestPush_CompleteWaitsForCleanupOfThePush795=== CONT TestPush_RepeatedRootCommitsOnce796=== CONT TestPush_CompleteCommitsEveryRoot797=== CONT TestPush_OverlappingRootsStoreOneRowPerKey798=== CONT TestReadRedirectUsesPublicS3URL799=== CONT TestReadProxyRangeRequest800=== CONT TestReadRedirectKeepsNarinfoProxied801=== CONT TestReadRedirectNar802=== CONT TestReadProxyDisabled803=== CONT TestReadProxyRootRedirectsToIndexHTML804=== CONT TestReadProxyConditionalGet805=== CONT TestReadProxyOutlastsServerWriteTimeout806=== CONT TestPresignedUploadRegisteredBeforeCommit8072026/10/10 19:42:26 INFO Received push request method=POST path=/api/pushes8082026/10/10 19:42:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8092026/10/10 19:42:26 INFO Signed narinfos id=1 count=18102026/10/10 19:42:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8112026/10/10 19:42:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8122026/10/10 19:42:26 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"8132026/10/10 19:42:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8142026/10/10 19:42:26 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"8152026/10/10 19:42:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8162026/10/10 19:42:26 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=18172026/10/10 19:42:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign8182026/10/10 19:42:26 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo819--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.32s)820=== CONT TestReadProxyNarinfo821--- PASS: TestPresentRefreshesOnlyStaleClosures (0.33s)822=== CONT TestIsValidCachePath823=== RUN TestIsValidCachePath/narinfo824=== PAUSE TestIsValidCachePath/narinfo825=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars826=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars827=== RUN TestIsValidCachePath/nar_zst828=== PAUSE TestIsValidCachePath/nar_zst829=== RUN TestIsValidCachePath/nar_xz830=== PAUSE TestIsValidCachePath/nar_xz831=== RUN TestIsValidCachePath/nar_bz2832=== PAUSE TestIsValidCachePath/nar_bz2833=== RUN TestIsValidCachePath/nar_uncompressed834=== PAUSE TestIsValidCachePath/nar_uncompressed835=== RUN TestIsValidCachePath/ls836=== PAUSE TestIsValidCachePath/ls837=== RUN TestIsValidCachePath/log838=== PAUSE TestIsValidCachePath/log839=== RUN TestIsValidCachePath/realisation840=== PAUSE TestIsValidCachePath/realisation841=== RUN TestIsValidCachePath/nix-cache-info842=== PAUSE TestIsValidCachePath/nix-cache-info843=== RUN TestIsValidCachePath/index.html844=== PAUSE TestIsValidCachePath/index.html845=== RUN TestIsValidCachePath/traversal_parent846=== PAUSE TestIsValidCachePath/traversal_parent847=== RUN TestIsValidCachePath/traversal_in_middle848=== PAUSE TestIsValidCachePath/traversal_in_middle849=== RUN TestIsValidCachePath/invalid_char_e850=== PAUSE TestIsValidCachePath/invalid_char_e851=== RUN TestIsValidCachePath/invalid_char_u852=== PAUSE TestIsValidCachePath/invalid_char_u853=== RUN TestIsValidCachePath/random_path854=== PAUSE TestIsValidCachePath/random_path855=== RUN TestIsValidCachePath/empty856=== PAUSE TestIsValidCachePath/empty857=== RUN TestIsValidCachePath/leading_slash858=== PAUSE TestIsValidCachePath/leading_slash859=== RUN TestIsValidCachePath/wrong_extension860=== PAUSE TestIsValidCachePath/wrong_extension861=== RUN TestIsValidCachePath/short_hash862=== PAUSE TestIsValidCachePath/short_hash863=== CONT TestParseSingleRange864=== RUN TestParseSingleRange/none865=== PAUSE TestParseSingleRange/none866=== RUN TestParseSingleRange/unknown_unit867=== PAUSE TestParseSingleRange/unknown_unit868=== RUN TestParseSingleRange/multi-range_ignored869=== PAUSE TestParseSingleRange/multi-range_ignored870=== RUN TestParseSingleRange/malformed_no_dash871=== PAUSE TestParseSingleRange/malformed_no_dash872=== RUN TestParseSingleRange/malformed_both_empty873=== PAUSE TestParseSingleRange/malformed_both_empty874=== RUN TestParseSingleRange/malformed_end_before_start875=== PAUSE TestParseSingleRange/malformed_end_before_start876=== RUN TestParseSingleRange/closed877=== PAUSE TestParseSingleRange/closed878=== RUN TestParseSingleRange/open-ended879=== PAUSE TestParseSingleRange/open-ended880=== RUN TestParseSingleRange/end_clamped_to_size881=== PAUSE TestParseSingleRange/end_clamped_to_size882=== RUN TestParseSingleRange/suffix883=== PAUSE TestParseSingleRange/suffix884=== RUN TestParseSingleRange/suffix_exceeds_size885=== PAUSE TestParseSingleRange/suffix_exceeds_size886=== RUN TestParseSingleRange/single_byte887=== PAUSE TestParseSingleRange/single_byte888=== RUN TestParseSingleRange/start_past_EOF889=== PAUSE TestParseSingleRange/start_past_EOF890=== RUN TestParseSingleRange/start_far_past_EOF891=== PAUSE TestParseSingleRange/start_far_past_EOF892=== CONT TestPresentNotReportedWhileGCDeletesClosure893=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale894=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale895=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh896=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh897=== CONT TestUploadHandlersRejectOversizedBody8982026/10/10 19:42:26 INFO Received uploads request method=POST path=/api/pending_closures8992026/10/10 19:42:26 INFO Received uploads request method=POST path=/api/pending_closures900=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart901=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart9022026/10/10 19:42:26 INFO Received push request method=POST path=/api/pushes903=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts904=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts905=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure906=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure907=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT9082026/10/10 19:42:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9092026/10/10 19:42:26 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NGM0ODBiNzctYjk2MC00YmIxLWFiMjUtZGZkMDIyMjZmNDczLjE3ZWY0ZWVlLTBlMWMtNDU1My04MmYwLTZiZjMwMzMwNTY0YngxNzkxNjYxMzQ2Njc1Mzg3MDI09102026/10/10 19:42:26 INFO Received complete push request method=POST path=/api/pushes/1/complete9112026/10/10 19:42:26 INFO Received push request method=POST path=/api/pushes9122026/10/10 19:42:26 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NGM0ODBiNzctYjk2MC00YmIxLWFiMjUtZGZkMDIyMjZmNDczLjE3ZWY0ZWVlLTBlMWMtNDU1My04MmYwLTZiZjMwMzMwNTY0YngxNzkxNjYxMzQ2Njc1Mzg3MDI0 parts=19132026/10/10 19:42:26 INFO Completed push id=1 objects=6 duration=10.42051ms914--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.52s)915=== CONT TestCompleteMultipartUnregistered916--- PASS: TestPush_CompleteCommitsEveryRoot (0.52s)917=== CONT TestService_verifyS3Integrity918--- PASS: TestService_Rustfstest (0.53s)919=== CONT TestService_createPendingClosureHandler920--- PASS: TestReadProxyRangeRequest (0.56s)921=== CONT TestReadProxyNarinfoAlreadyDecompressed922--- PASS: TestReadProxyHead (0.60s)923=== CONT TestReadProxyInvalidPath924=== RUN TestPush_RejectsBadRequests/bad_root925=== PAUSE TestPush_RejectsBadRequests/bad_root926=== RUN TestPush_RejectsBadRequests/root_not_in_objects927=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects928=== RUN TestPush_RejectsBadRequests/no_roots929=== PAUSE TestPush_RejectsBadRequests/no_roots930=== RUN TestPush_RejectsBadRequests/no_objects931=== PAUSE TestPush_RejectsBadRequests/no_objects932=== CONT TestReadProxy4049332026/10/10 19:42:26 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"934--- PASS: TestService_AuthMiddleware (0.62s)935=== CONT TestService_cleanupPendingClosuresHandler9362026/10/10 19:42:26 INFO Received push request method=POST path=/api/pushes937--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.66s)938=== CONT TestReadProxyNarStreaming939--- PASS: TestReadRedirectUsesPublicS3URL (0.68s)940=== CONT TestPresentReportsOnlyClosureRoots941--- PASS: TestReadRedirectNar (0.69s)942=== CONT TestReadProxyContentNegotiation9432026/10/10 19:42:26 INFO Received uploads request method=POST path=/api/pending_closures9442026/10/10 19:42:26 INFO Received uploads request method=POST path=/api/pending_closures945--- PASS: TestReadProxyDisabled (0.72s)946=== CONT TestCreatePin_ReservedPins947--- PASS: TestReadProxyConditionalGet (0.76s)948=== CONT TestService_NativeMTLS949--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.77s)950=== CONT TestOrphanedObjectsGCStressTest9512026/10/10 19:42:27 INFO Received push request method=POST path=/api/pushes9522026/10/10 19:42:27 INFO Received complete push request method=POST path=/api/pushes/1/complete9532026/10/10 19:42:27 INFO Completed push id=1 objects=4 duration=9.521123ms9542026/10/10 19:42:27 INFO Received push request method=POST path=/api/pushes9552026-10-10 19:42:27.102 UTC [489] ERROR: Push does not exist: id=19562026-10-10 19:42:27.102 UTC [489] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE9572026-10-10 19:42:27.102 UTC [489] STATEMENT: SELECT commit_push($1)958--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.82s)959=== CONT TestOrphanedObjectsGC960--- PASS: TestReadRedirectKeepsNarinfoProxied (0.82s)961=== CONT TestGenerateLandingPage9622026/10/10 19:42:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40781/oidc963--- PASS: TestGenerateLandingPage (0.00s)964=== CONT TestObjectStatsLargeCommit9652026/10/10 19:42:27 INFO Received push request method=POST path=/api/pushes9662026/10/10 19:42:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9672026/10/10 19:42:27 INFO Received complete push request method=POST path=/api/pushes/1/complete9682026/10/10 19:42:27 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NGM0ODBiNzctYjk2MC00YmIxLWFiMjUtZGZkMDIyMjZmNDczLjIxODk3NzQyLTg0ZjYtNDU1Mi05MGU1LWQ2NGIzYjBkYzkxOHgxNzkxNjYxMzQ2Njc2MDAxNjQ5 parts=129692026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures9702026/10/10 19:42:27 INFO Completed push id=1 objects=4 duration=10.680473ms971--- PASS: TestPush_RepeatedRootCommitsOnce (0.87s)972=== CONT TestMetricsCommit973--- PASS: TestCompletedNarNotReofferedAcrossClosures (0.87s)974=== CONT TestObjectStatsTrigger9752026/10/10 19:42:27 INFO Received push request method=POST path=/api/pushes9762026/10/10 19:42:27 INFO Aborted multipart uploads count=0 kept=09772026/10/10 19:42:27 WARN Force mode enabled - objects will be deleted immediately without grace period9782026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures9792026/10/10 19:42:27 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=09802026/10/10 19:42:27 INFO Vacuumed table table=pending_closures9812026/10/10 19:42:27 INFO Vacuumed table table=pending_objects9822026/10/10 19:42:27 INFO Vacuumed table table=multipart_uploads9832026/10/10 19:42:27 INFO Vacuumed table table=closures9842026/10/10 19:42:27 INFO Vacuumed table table=objects9852026/10/10 19:42:27 INFO Received complete push request method=POST path=/api/pushes/2/complete9862026/10/10 19:42:27 INFO Completed push id=2 objects=4 duration=3.398529ms9872026/10/10 19:42:27 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9882026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures989--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.92s)990=== CONT TestMetricsInventory9912026-10-10 19:42:27.196 UTC [562] ERROR: could not obtain lock on row in relation "closures"9922026-10-10 19:42:27.196 UTC [562] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT993--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.91s)994=== CONT TestPendingCleanupUsesOneCutoff9952026-10-10 19:42:27.197 UTC [562] ERROR: could not obtain lock on row in relation "closures"9962026-10-10 19:42:27.197 UTC [562] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9972026-10-10 19:42:27.198 UTC [562] ERROR: could not obtain lock on row in relation "closures"9982026-10-10 19:42:27.198 UTC [562] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9992026-10-10 19:42:27.198 UTC [562] ERROR: could not obtain lock on row in relation "closures"10002026-10-10 19:42:27.198 UTC [562] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10012026-10-10 19:42:27.199 UTC [562] ERROR: could not obtain lock on row in relation "closures"10022026-10-10 19:42:27.199 UTC [562] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1003--- PASS: TestPush_RootsAreLockedInByteOrder (0.93s)1004=== CONT TestNARDeduplicationMetadataUploadBug10052026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures1006--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.47s)1007=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded10082026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures10092026/10/10 19:42:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10102026/10/10 19:42:27 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1011--- PASS: TestCompleteMultipartUnregistered (0.47s)1012=== CONT TestCreatePendingClosureRejectsOversizedNAR10132026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures1014--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1015=== CONT TestMultipartCleanup10162026/10/10 19:42:27 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1017--- PASS: TestReadProxyNarinfo (0.68s)1018=== CONT TestCacheConfigHandlerMaxNarSize1019--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1020=== CONT TestServerTLSConfig1021=== RUN TestServerTLSConfig/no_client_CA1022=== PAUSE TestServerTLSConfig/no_client_CA1023=== RUN TestServerTLSConfig/missing_CA_file1024=== PAUSE TestServerTLSConfig/missing_CA_file1025=== RUN TestServerTLSConfig/not_a_PEM_file1026=== PAUSE TestServerTLSConfig/not_a_PEM_file1027=== CONT TestPendingClosureWriteTimeout1028=== RUN TestPendingClosureWriteTimeout/empty1029=== PAUSE TestPendingClosureWriteTimeout/empty1030=== RUN TestPendingClosureWriteTimeout/400_objects1031=== PAUSE TestPendingClosureWriteTimeout/400_objects1032=== RUN TestPendingClosureWriteTimeout/670k_objects1033=== PAUSE TestPendingClosureWriteTimeout/670k_objects1034=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1035=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1036=== CONT TestLeadEndsOnShutdown10372026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures10382026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures10392026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures1040--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.48s)1041=== CONT TestUploadHandlersRejectInvalidKeys1042=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1043=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1044=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1045=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1046=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1047=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1048=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1049=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1050=== CONT TestGCTaskStore_GetReturnsLatest1051--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1052=== CONT TestIsValidUploadKey1053=== RUN TestIsValidUploadKey/narinfo1054=== PAUSE TestIsValidUploadKey/narinfo1055=== RUN TestIsValidUploadKey/nar_zst1056=== PAUSE TestIsValidUploadKey/nar_zst1057=== RUN TestIsValidUploadKey/nar_xz1058=== PAUSE TestIsValidUploadKey/nar_xz1059=== RUN TestIsValidUploadKey/nar_plain1060=== PAUSE TestIsValidUploadKey/nar_plain1061=== RUN TestIsValidUploadKey/listing1062=== PAUSE TestIsValidUploadKey/listing1063=== RUN TestIsValidUploadKey/build_log1064=== PAUSE TestIsValidUploadKey/build_log1065=== RUN TestIsValidUploadKey/build_log_home-manager_file1066=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1067=== RUN TestIsValidUploadKey/build_log_plus_in_name1068=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1069=== RUN TestIsValidUploadKey/build_log_question_mark1070=== PAUSE TestIsValidUploadKey/build_log_question_mark1071=== RUN TestIsValidUploadKey/build_log_equals1072=== PAUSE TestIsValidUploadKey/build_log_equals1073=== RUN TestIsValidUploadKey/realisation1074=== PAUSE TestIsValidUploadKey/realisation1075=== RUN TestIsValidUploadKey/realisation_plus_in_output1076=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1077=== RUN TestIsValidUploadKey/nix-cache-info1078=== PAUSE TestIsValidUploadKey/nix-cache-info1079=== RUN TestIsValidUploadKey/index.html1080=== PAUSE TestIsValidUploadKey/index.html1081=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1082=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1083=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1084=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1085=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1086=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1087=== RUN TestIsValidUploadKey/traversal1088=== PAUSE TestIsValidUploadKey/traversal1089=== RUN TestIsValidUploadKey/traversal_nar1090=== PAUSE TestIsValidUploadKey/traversal_nar1091=== RUN TestIsValidUploadKey/absolute1092=== PAUSE TestIsValidUploadKey/absolute1093=== RUN TestIsValidUploadKey/empty_key1094=== PAUSE TestIsValidUploadKey/empty_key1095=== RUN TestIsValidUploadKey/unknown_type1096=== PAUSE TestIsValidUploadKey/unknown_type1097=== CONT TestGCTaskStore_GetEmpty1098--- PASS: TestGCTaskStore_GetEmpty (0.00s)1099=== CONT TestGracefulShutdownDrainsInflight11002026/10/10 19:42:27 INFO Starting HTTP server address=127.0.0.1:4162911012026/10/10 19:42:27 INFO Shutdown signal received, draining in-flight requests timeout=10s1102--- PASS: TestReadProxyInvalidPath (0.47s)1103=== CONT TestGCTaskStore_ConflictDifferentParams1104--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1105=== CONT TestService_readinessHandler11062026/10/10 19:42:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11072026/10/10 19:42:27 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NGM0ODBiNzctYjk2MC00YmIxLWFiMjUtZGZkMDIyMjZmNDczLmRlMjhkNzhhLWM2OGItNDQ4Mi1iMjY4LWRmZGQyODk5NDUzNXgxNzkxNjYxMzQ2OTkxMDUzMTUy parts=1211082026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures11092026/10/10 19:42:27 INFO Received cleanup request method=DELETE path=/api/pending_closures1110--- PASS: TestReadProxy404 (0.51s)1111=== CONT TestGCTaskStore_DeduplicateSameParams1112--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1113=== CONT TestService_healthCheckHandler11142026/10/10 19:42:27 INFO Aborted multipart uploads count=0 kept=011152026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures11162026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures1117--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1118=== CONT TestGCTaskStore_StartNew1119--- PASS: TestGCTaskStore_StartNew (0.00s)1120=== CONT TestGCEndsOnShutdown1121=== RUN TestGCEndsOnShutdown/before_the_run1122=== PAUSE TestGCEndsOnShutdown/before_the_run1123=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1124=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1125=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1126=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1127=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection11282026/10/10 19:42:27 INFO Received cleanup request method=DELETE path=/api/pending_closures11292026/10/10 19:42:27 INFO Aborted multipart uploads count=1 kept=011302026/10/10 19:42:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11312026-10-10 19:42:27.408 UTC [514] ERROR: Closure does not exist: id=111322026-10-10 19:42:27.408 UTC [514] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE11332026-10-10 19:42:27.408 UTC [514] STATEMENT: -- name: CommitPendingClosure :one1134 SELECT commit_pending_closure($1::bigint)::bigint1135 1136--- PASS: TestService_cleanupPendingClosuresHandler (0.51s)1137=== CONT TestGCSweepDeliversEachKeyOnce1138--- PASS: TestReadProxyNarStreaming (0.48s)1139=== CONT TestCommitRacingPendingCleanupKeepsObjects1140--- PASS: TestPresentReportsOnlyClosureRoots (0.49s)1141=== CONT TestTombstonedObjectOfferedWithoutWaiting11422026/10/10 19:42:27 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11432026/10/10 19:42:27 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1144--- PASS: TestService_NativeMTLS (0.45s)1145=== CONT TestPushWaitsForSweepHoldingRow1146--- PASS: TestReadProxyContentNegotiation (0.56s)1147=== CONT TestGCSweepSkipsPendingObjects11482026/10/10 19:42:27 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11492026/10/10 19:42:27 WARN Refused reserved pin name=worker-x86_64-linux11502026/10/10 19:42:27 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11512026/10/10 19:42:27 INFO Received create pin request method=POST path=/api/pins/my-app11522026/10/10 19:42:27 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1153--- PASS: TestCreatePin_ReservedPins (0.57s)1154=== CONT TestSweepRechecksPendingAfterLocking11552026/10/10 19:42:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11562026/10/10 19:42:27 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NGM0ODBiNzctYjk2MC00YmIxLWFiMjUtZGZkMDIyMjZmNDczLjFjYmMwMGRjLWRiMmYtNGNkNi04MTI2LTRmYjA2NmYwMTdiN3gxNzkxNjYxMzQ3MjU1NTk0Mjc2 parts=1011572026/10/10 19:42:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11582026/10/10 19:42:27 INFO Completed upload id=1 objects=2 duration=3.210248ms11592026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures11602026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures11612026/10/10 19:42:27 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11622026/10/10 19:42:27 WARN Found objects in DB but missing from S3, will re-upload count=111632026/10/10 19:42:27 INFO Received push request method=POST path=/api/pushes1164--- PASS: TestService_verifyS3Integrity (0.81s)1165=== CONT TestDeduplicatedObjectsRecordedAsPending11662026/10/10 19:42:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11672026/10/10 19:42:27 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NGM0ODBiNzctYjk2MC00YmIxLWFiMjUtZGZkMDIyMjZmNDczLmQxNTFkZjYwLWQ2ZGEtNGI2MS05N2YwLWY4NzRhOTY0Zjg0ZHgxNzkxNjYxMzQ3MzAwOTgwMDkx parts=1011682026/10/10 19:42:27 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11692026/10/10 19:42:27 INFO Received complete push request method=POST path=/api/pushes/1/complete11702026/10/10 19:42:27 INFO Completed upload id=1 objects=2 duration=3.797894ms11712026/10/10 19:42:27 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011722026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures11732026/10/10 19:42:27 INFO Starting cleanup of old closures method=DELETE path=/api/closures11742026/10/10 19:42:27 INFO Completed push id=1 objects=4 duration=10.615592ms11752026/10/10 19:42:27 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11762026/10/10 19:42:27 INFO Completed upload id=2 objects=2 duration=1.737615ms11772026/10/10 19:42:27 INFO Aborted multipart uploads count=0 kept=01178--- PASS: TestMetricsCommit (0.49s)1179=== CONT TestGetExistingObjectsLocksRows1180--- PASS: TestObjectStatsTrigger (0.49s)1181=== CONT TestPushDedupSurvivesConcurrentGC11822026/10/10 19:42:27 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=011832026/10/10 19:42:27 INFO Vacuumed table table=pending_closures11842026/10/10 19:42:27 INFO Vacuumed table table=pending_objects11852026/10/10 19:42:27 INFO Vacuumed table table=multipart_uploads11862026/10/10 19:42:27 INFO Vacuumed table table=closures11872026/10/10 19:42:27 INFO Vacuumed table table=objects1188--- PASS: TestMetricsInventory (0.47s)1189=== CONT TestRegisterCompletedObjectNeedsPendingRow11902026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures11912026/10/10 19:42:27 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001192--- PASS: TestService_createPendingClosureHandler (0.87s)1193=== CONT TestGCMetrics11942026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures11952026/10/10 19:42:27 INFO Received cleanup request method=DELETE path=/api/pending_closures11962026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures1197--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.50s)1198=== CONT TestSweepSkipsRowsLockedByPush1199=== NAME TestNARDeduplicationMetadataUploadBug1200 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug1416825276/001/store/hnqn9vxlzqm21c5b0rnmijlpxnivqdzv-file1.txt12012026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures12022026/10/10 19:42:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12032026/10/10 19:42:27 INFO lead: acquired remote=192.0.2.1:123412042026/10/10 19:42:27 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NGM0ODBiNzctYjk2MC00YmIxLWFiMjUtZGZkMDIyMjZmNDczLjE1MDg1ZDFmLTE4ODEtNDFiNS1iYmVkLTg2NmI4NDhiNjYxYXgxNzkxNjYxMzQ3Mzk1MDMxNzUw error="Get \"http://127.0.0.1:1/bucket18/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"12052026/10/10 19:42:27 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NGM0ODBiNzctYjk2MC00YmIxLWFiMjUtZGZkMDIyMjZmNDczLjlhODExYmY4LTU5MmQtNDFhZS04NmJlLWIyZTJmN2IwMGRiYngxNzkxNjYxMzQ3Mzg4ODM1NzM2 parts=1212062026/10/10 19:42:27 INFO Received cleanup request method=DELETE path=/api/pending_closures12072026/10/10 19:42:27 INFO Aborted multipart uploads count=1 kept=01208--- PASS: TestRedundantMultipartUpload (1.51s)1209=== CONT TestGCBugBareHashReferences12102026/10/10 19:42:27 WARN readiness check failed error="closed pool"1211--- PASS: TestService_readinessHandler (0.44s)1212=== CONT TestFailedS3DeleteKeepsTombstone1213--- PASS: TestService_healthCheckHandler (0.42s)1214=== CONT TestGCAdvisoryLockBlocksConcurrentRun12152026/10/10 19:42:27 INFO Received push request method=POST path=/api/pushes12162026/10/10 19:42:27 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12172026/10/10 19:42:27 INFO Uploading hnqn9vxlzqm21c5b0rnmijlpxnivqdzv-file1.txt (160B)12182026/10/10 19:42:27 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12192026/10/10 19:42:27 WARN Failed to register uploaded object key=hnqn9vxlzqm21c5b0rnmijlpxnivqdzv.ls error="server returned 404: 404 page not found\n"12202026/10/10 19:42:27 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12212026/10/10 19:42:27 INFO Signed narinfos id=1 count=112222026/10/10 19:42:27 INFO Uploading 1 narinfos12232026/10/10 19:42:27 INFO Received complete push request method=POST path=/api/pushes/1/complete12242026/10/10 19:42:27 WARN Failed to register uploaded object key=hnqn9vxlzqm21c5b0rnmijlpxnivqdzv.narinfo error="server returned 404: 404 page not found\n"12252026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures12262026/10/10 19:42:27 INFO Completed push id=1 objects=3 duration=7.427624ms12272026/10/10 19:42:27 INFO Upload complete. (65ms)1228=== NAME TestNARDeduplicationMetadataUploadBug1229 metadata_upload_test.go:54: Retrieved narinfo from S3:1230 StorePath: /build/TestNARDeduplicationMetadataUploadBug1416825276/001/store/hnqn9vxlzqm21c5b0rnmijlpxnivqdzv-file1.txt1231 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1232 Compression: zstd1233 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1234 NarSize: 1601235 References: 1236 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1237 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1238 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1239 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}12402026/10/10 19:42:27 INFO Received cleanup request method=DELETE path=/api/pending_closures12412026/10/10 19:42:27 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket51/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12422026/10/10 19:42:27 INFO Aborted multipart uploads count=0 kept=112432026/10/10 19:42:27 INFO Received cleanup request method=DELETE path=/api/pending_closures1244=== NAME TestOrphanedObjectsGC1245 orphaned_objects_gc_test.go:287: GC Test Summary:1246 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1247 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1248 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1249 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1250 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1251--- PASS: TestOrphanedObjectsGC (0.76s)1252=== CONT TestForceGCDuringPushOffersSweptObject1253=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1254=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1255=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1256=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1257=== CONT TestClientMultipleUploads12582026/10/10 19:42:27 INFO Aborted multipart uploads count=1 kept=01259--- PASS: TestMultipartCleanup (0.60s)1260=== CONT TestService_ReadScope_PublicByDefault1261=== NAME TestNARDeduplicationMetadataUploadBug1262 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug1416825276/001/store/l5q859bicrhq4lc7limfp7i886ax9wcl-file2.txt12632026/10/10 19:42:27 INFO Aborted multipart uploads count=0 kept=012642026/10/10 19:42:27 WARN Force mode enabled - objects will be deleted immediately without grace period12652026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures12662026/10/10 19:42:27 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=012672026/10/10 19:42:27 INFO Vacuumed table table=pending_closures12682026/10/10 19:42:27 INFO Vacuumed table table=pending_objects12692026/10/10 19:42:27 INFO Vacuumed table table=multipart_uploads12702026/10/10 19:42:27 INFO Vacuumed table table=closures1271--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.47s)1272=== CONT TestLeadIncumbentAnnouncesAtOnce12732026/10/10 19:42:27 INFO Vacuumed table table=objects1274--- PASS: TestGCSweepDeliversEachKeyOnce (0.51s)1275=== CONT TestClientIntegration12762026/10/10 19:42:27 INFO Aborted multipart uploads count=0 kept=012772026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures12782026/10/10 19:42:27 WARN Force mode enabled - objects will be deleted immediately without grace period12792026/10/10 19:42:27 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=012802026/10/10 19:42:27 INFO Vacuumed table table=pending_closures12812026/10/10 19:42:27 INFO Vacuumed table table=pending_objects12822026/10/10 19:42:27 INFO Vacuumed table table=multipart_uploads12832026/10/10 19:42:27 INFO Vacuumed table table=closures12842026/10/10 19:42:27 INFO Vacuumed table table=objects12852026/10/10 19:42:27 INFO Received push request method=POST path=/api/pushes12862026/10/10 19:42:27 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12872026/10/10 19:42:27 INFO Received uploads request method=POST path=/api/pending_closures1288--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.54s)1289=== CONT TestLeadElectsOneAndHandsOver12902026/10/10 19:42:27 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12912026/10/10 19:42:27 WARN Failed to register uploaded object key=l5q859bicrhq4lc7limfp7i886ax9wcl.ls error="server returned 404: 404 page not found\n"12922026/10/10 19:42:27 INFO Signed narinfos id=2 count=112932026/10/10 19:42:27 INFO Uploading 1 narinfos12942026/10/10 19:42:27 INFO Received complete push request method=POST path=/api/pushes/2/complete12952026/10/10 19:42:27 WARN Failed to register uploaded object key=l5q859bicrhq4lc7limfp7i886ax9wcl.narinfo error="server returned 404: 404 page not found\n"12962026/10/10 19:42:27 INFO Aborted multipart uploads count=0 kept=012972026/10/10 19:42:27 INFO Completed push id=2 objects=3 duration=8.170312ms12982026/10/10 19:42:27 INFO Upload complete. (59ms)1299=== NAME TestNARDeduplicationMetadataUploadBug1300 metadata_upload_test.go:76: Retrieved narinfo from S3:1301 StorePath: /build/TestNARDeduplicationMetadataUploadBug1416825276/001/store/l5q859bicrhq4lc7limfp7i886ax9wcl-file2.txt1302 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1303 Compression: zstd1304 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1305 NarSize: 1601306 References: 1307 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1308 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1309 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1310 {"version":1,"root":{"type":"regular","size":44}}13112026/10/10 19:42:27 WARN Force mode enabled - objects will be deleted immediately without grace period1312--- PASS: TestNARDeduplicationMetadataUploadBug (0.78s)1313=== CONT TestClientErrorHandling1314=== RUN TestClientErrorHandling/InvalidStorePath1315=== PAUSE TestClientErrorHandling/InvalidStorePath1316=== RUN TestClientErrorHandling/InvalidAuthToken1317=== PAUSE TestClientErrorHandling/InvalidAuthToken1318=== RUN TestClientErrorHandling/ServerNotAvailable1319=== PAUSE TestClientErrorHandling/ServerNotAvailable1320=== CONT TestConnectWaitsForAPeerMigration13212026/10/10 19:42:27 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=013222026/10/10 19:42:27 INFO Vacuumed table table=pending_closures13232026/10/10 19:42:27 INFO Vacuumed table table=pending_objects13242026/10/10 19:42:27 INFO Vacuumed table table=multipart_uploads13252026/10/10 19:42:27 INFO Vacuumed table table=closures13262026/10/10 19:42:27 INFO Vacuumed table table=objects13272026/10/10 19:42:27 INFO Aborted multipart uploads count=0 kept=013282026/10/10 19:42:28 WARN Force mode enabled - objects will be deleted immediately without grace period1329--- PASS: TestGCSweepSkipsPendingObjects (0.47s)1330=== CONT TestClientCADerivations13312026/10/10 19:42:28 INFO Received uploads request method=POST path=/api/pending_closures1332--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.41s)1333=== CONT TestResolveDBConnectionString1334=== RUN TestResolveDBConnectionString/flag_wins1335=== PAUSE TestResolveDBConnectionString/flag_wins1336=== RUN TestResolveDBConnectionString/file_when_flag_empty1337=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1338=== RUN TestResolveDBConnectionString/missing_file_is_an_error1339=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1340=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1341=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1342=== RUN TestResolveDBConnectionString/nothing_configured1343=== PAUSE TestResolveDBConnectionString/nothing_configured1344=== CONT TestCacheStatsHandler13452026/10/10 19:42:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013462026/10/10 19:42:28 INFO Vacuumed table table=pending_closures13472026/10/10 19:42:28 INFO Vacuumed table table=pending_objects13482026/10/10 19:42:28 INFO Vacuumed table table=multipart_uploads13492026/10/10 19:42:28 INFO Vacuumed table table=closures13502026/10/10 19:42:28 INFO Vacuumed table table=objects1351--- PASS: TestSweepRechecksPendingAfterLocking (0.45s)1352=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1353--- PASS: TestGetExistingObjectsLocksRows (0.40s)1354=== CONT TestCacheConfigHandler1355=== RUN TestCacheConfigHandler/full_config,_no_issuer1356=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1357=== RUN TestCacheConfigHandler/no_cache_url_configured1358=== PAUSE TestCacheConfigHandler/no_cache_url_configured1359=== RUN TestCacheConfigHandler/no_signing_keys1360=== PAUSE TestCacheConfigHandler/no_signing_keys1361=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1362=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1363=== CONT TestDeleteClosuresRacingPins1364--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.65s)1365=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle13662026/10/10 19:42:28 INFO Received uploads request method=POST path=/api/pending_closures1367--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.41s)1368=== CONT TestClientFallsBackToClosures13692026/10/10 19:42:28 INFO Aborted multipart uploads count=0 kept=013702026/10/10 19:42:28 WARN Force mode enabled - objects will be deleted immediately without grace period13712026/10/10 19:42:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013722026/10/10 19:42:28 INFO Vacuumed table table=pending_closures13732026/10/10 19:42:28 INFO Vacuumed table table=pending_objects13742026/10/10 19:42:28 INFO Vacuumed table table=multipart_uploads13752026/10/10 19:42:28 INFO Vacuumed table table=closures13762026/10/10 19:42:28 INFO Vacuumed table table=objects1377--- PASS: TestGCMetrics (0.44s)1378=== CONT TestProxyWriteTimeout1379=== RUN TestProxyWriteTimeout/narinfo1380=== PAUSE TestProxyWriteTimeout/narinfo1381=== RUN TestProxyWriteTimeout/1_GiB_nar1382=== PAUSE TestProxyWriteTimeout/1_GiB_nar1383=== RUN TestProxyWriteTimeout/10_GiB_nar1384=== PAUSE TestProxyWriteTimeout/10_GiB_nar1385=== RUN TestProxyWriteTimeout/unknown_size1386=== PAUSE TestProxyWriteTimeout/unknown_size1387=== CONT TestClientPushesUseOnePush13882026/10/10 19:42:28 INFO Aborted multipart uploads count=0 kept=013892026/10/10 19:42:28 INFO Aborted multipart uploads count=0 kept=013902026/10/10 19:42:28 WARN Force mode enabled - objects will be deleted immediately without grace period13912026/10/10 19:42:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=013922026/10/10 19:42:28 INFO Vacuumed table table=pending_closures13932026/10/10 19:42:28 INFO Vacuumed table table=pending_objects13942026/10/10 19:42:28 INFO Vacuumed table table=multipart_uploads13952026/10/10 19:42:28 INFO Vacuumed table table=closures13962026/10/10 19:42:28 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=013972026/10/10 19:42:28 INFO Vacuumed table table=objects13982026/10/10 19:42:28 INFO Vacuumed table table=pending_closures13992026/10/10 19:42:28 INFO Vacuumed table table=pending_objects14002026/10/10 19:42:28 INFO Vacuumed table table=multipart_uploads14012026/10/10 19:42:28 INFO Aborted multipart uploads count=0 kept=014022026/10/10 19:42:28 INFO Vacuumed table table=closures14032026/10/10 19:42:28 INFO Received uploads request method=POST path=/api/pending_closures14042026/10/10 19:42:28 INFO Vacuumed table table=objects14052026/10/10 19:42:28 WARN Force mode enabled - objects will be deleted immediately without grace period14062026/10/10 19:42:28 INFO Aborted multipart uploads count=0 kept=014072026/10/10 19:42:28 WARN Force mode enabled - objects will be deleted immediately without grace period14082026/10/10 19:42:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014092026/10/10 19:42:28 INFO Vacuumed table table=pending_closures14102026/10/10 19:42:28 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=014112026/10/10 19:42:28 INFO Vacuumed table table=pending_closures14122026/10/10 19:42:28 INFO Vacuumed table table=pending_objects14132026/10/10 19:42:28 INFO Vacuumed table table=multipart_uploads14142026/10/10 19:42:28 INFO Vacuumed table table=closures14152026/10/10 19:42:28 INFO Vacuumed table table=pending_objects14162026/10/10 19:42:28 INFO Vacuumed table table=multipart_uploads14172026/10/10 19:42:28 INFO Vacuumed table table=closures14182026/10/10 19:42:28 INFO Vacuumed table table=objects14192026/10/10 19:42:28 INFO Vacuumed table table=objects1420--- PASS: TestSweepSkipsRowsLockedByPush (0.45s)1421=== CONT TestGCTaskStore_Fail1422--- PASS: TestGCTaskStore_Fail (0.00s)1423=== CONT TestGCTaskStore_PhaseUpdates1424=== CONT TestClientSharedPathCommittedMidPush1425--- PASS: TestPushDedupSurvivesConcurrentGC (0.54s)1426--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1427=== CONT TestPinProtectsFromGC14282026/10/10 19:42:28 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"1429--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.38s)1430=== CONT TestClientWithDependencies1431--- PASS: TestService_ReadScope_PublicByDefault (0.36s)1432=== CONT TestSkippedUploadsHandler14332026/10/10 19:42:28 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001434--- PASS: TestSkippedUploadsHandler (0.00s)1435=== CONT TestService_ReadAuthMiddleware14362026/10/10 19:42:28 INFO Aborted multipart uploads count=0 kept=01437=== NAME TestClientMultipleUploads1438 client_integration_test.go:358: Created store path 0: /build/TestClientMultipleUploads2277089473/001/store/7xbgpsa8d6grp6qw97frs2yja96pdv2a-test-file-0.txt14392026/10/10 19:42:28 WARN Force mode enabled - objects will be deleted immediately without grace period14402026/10/10 19:42:28 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."14412026/10/10 19:42:28 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1442--- PASS: TestFailedS3DeleteKeepsTombstone (0.47s)1443=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14442026/10/10 19:42:28 INFO lead: acquired remote=192.0.2.1:123414452026/10/10 19:42:28 INFO lead: released remote=192.0.2.1:12341446--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.35s)1447=== CONT TestService_AuthMiddleware_OIDC1448=== NAME TestClientMultipleUploads1449 client_integration_test.go:358: Created store path 1: /build/TestClientMultipleUploads2277089473/001/store/am7wf1505nc705abvpzw54hyjcm00h7q-test-file-1.txt14502026/10/10 19:42:28 INFO lead: acquired remote=192.0.2.1:12341451=== NAME TestClientIntegration1452 client_integration_test.go:286: Created store path: /build/TestClientIntegration897935861/002/store/szybjmpr8dc60ix4cnqrkvaysqrp719s-test-file.txt1453=== NAME TestClientMultipleUploads1454 client_integration_test.go:358: Created store path 2: /build/TestClientMultipleUploads2277089473/001/store/rigs2i4w6nr4m9i648d87v3sdfy8k8pn-test-file-2.txt1455--- PASS: TestCacheStatsHandler (0.32s)1456=== CONT TestService_AuthMiddleware_MTLSProxyHeader14572026/10/10 19:42:28 INFO Received push request method=POST path=/api/pushes14582026/10/10 19:42:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14592026/10/10 19:42:28 INFO Uploading szybjmpr8dc60ix4cnqrkvaysqrp719s-test-file.txt (152B)1460--- PASS: TestGCBugBareHashReferences (0.58s)1461=== CONT TestService_RequireScope_OIDC14622026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"14632026/10/10 19:42:28 WARN Failed to register uploaded object key=szybjmpr8dc60ix4cnqrkvaysqrp719s.ls error="server returned 404: 404 page not found\n"14642026/10/10 19:42:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14652026/10/10 19:42:28 INFO Signed narinfos id=1 count=114662026/10/10 19:42:28 INFO Uploading 1 narinfos14672026/10/10 19:42:28 INFO Received complete push request method=POST path=/api/pushes/1/complete14682026/10/10 19:42:28 WARN Failed to register uploaded object key=szybjmpr8dc60ix4cnqrkvaysqrp719s.narinfo error="server returned 404: 404 page not found\n"14692026/10/10 19:42:28 INFO Received uploads request method=POST path=/api/pending_closures14702026/10/10 19:42:28 INFO Completed push id=1 objects=3 duration=11.296879ms14712026/10/10 19:42:28 INFO Upload complete. (71ms)1472=== NAME TestClientCADerivations1473 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations3196708573/001/store/ls28aycl57pdmnnisbmwa1bpjy0vfr3c-ca-test14742026/10/10 19:42:28 INFO Received push request method=POST path=/api/pushes14752026/10/10 19:42:28 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)14762026/10/10 19:42:28 INFO Uploading rigs2i4w6nr4m9i648d87v3sdfy8k8pn-test-file-2.txt (160B)14772026/10/10 19:42:28 INFO Uploading am7wf1505nc705abvpzw54hyjcm00h7q-test-file-1.txt (160B)14782026/10/10 19:42:28 INFO Uploading 7xbgpsa8d6grp6qw97frs2yja96pdv2a-test-file-0.txt (160B)14792026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"14802026/10/10 19:42:28 WARN Failed to register uploaded object key=rigs2i4w6nr4m9i648d87v3sdfy8k8pn.ls error="server returned 404: 404 page not found\n"14812026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"14822026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"14832026/10/10 19:42:28 WARN Failed to register uploaded object key=am7wf1505nc705abvpzw54hyjcm00h7q.ls error="server returned 404: 404 page not found\n"14842026/10/10 19:42:28 WARN Failed to register uploaded object key=7xbgpsa8d6grp6qw97frs2yja96pdv2a.ls error="server returned 404: 404 page not found\n"14852026/10/10 19:42:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14862026/10/10 19:42:28 INFO Signed narinfos id=1 count=314872026/10/10 19:42:28 INFO Uploading 3 narinfos14882026/10/10 19:42:28 WARN Failed to register uploaded object key=7xbgpsa8d6grp6qw97frs2yja96pdv2a.narinfo error="server returned 404: 404 page not found\n"14892026/10/10 19:42:28 INFO Received complete push request method=POST path=/api/pushes/1/complete14902026/10/10 19:42:28 WARN Failed to register uploaded object key=am7wf1505nc705abvpzw54hyjcm00h7q.narinfo error="server returned 404: 404 page not found\n"14912026/10/10 19:42:28 WARN Failed to register uploaded object key=rigs2i4w6nr4m9i648d87v3sdfy8k8pn.narinfo error="server returned 404: 404 page not found\n"1492 client_ca_test.go:139: Found 1 dependencies (including self)14932026/10/10 19:42:28 INFO Completed push id=1 objects=9 duration=8.435993ms14942026/10/10 19:42:28 INFO Upload complete. (71ms)1495=== NAME TestClientMultipleUploads1496 client_integration_test.go:369: Uploaded 3 paths in 105.136316ms14972026/10/10 19:42:28 INFO All 1 paths already cached1498=== NAME TestClientIntegration1499 client_integration_test.go:312: Retrieved narinfo from S3:1500 StorePath: /build/TestClientIntegration897935861/002/store/szybjmpr8dc60ix4cnqrkvaysqrp719s-test-file.txt1501 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1502 Compression: zstd1503 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11504 NarSize: 1521505 References: 1506 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11507 client_integration_test.go:313: Retrieved .ls file from S3 (compressed size: 77 bytes)1508 client_integration_test.go:313: Decompressed .ls content (64 bytes):1509 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1510 client_integration_test.go:316: Testing garbage collection...1511--- PASS: TestClientMultipleUploads (0.57s)1512=== CONT TestIsValidCachePath/narinfo1513=== CONT TestIsValidCachePath/index.html1514=== CONT TestIsValidCachePath/short_hash1515=== CONT TestIsValidCachePath/wrong_extension1516=== CONT TestIsValidCachePath/leading_slash1517=== CONT TestIsValidCachePath/empty1518=== CONT TestIsValidCachePath/random_path1519=== CONT TestIsValidCachePath/invalid_char_u1520=== CONT TestIsValidCachePath/invalid_char_e1521=== CONT TestIsValidCachePath/traversal_in_middle1522=== CONT TestIsValidCachePath/traversal_parent1523=== CONT TestIsValidCachePath/nar_uncompressed1524=== CONT TestIsValidCachePath/log1525=== CONT TestIsValidCachePath/realisation1526=== CONT TestIsValidCachePath/nix-cache-info1527=== CONT TestIsValidCachePath/nar_xz1528=== CONT TestIsValidCachePath/nar_bz21529=== CONT TestIsValidCachePath/nar_zst1530=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1531=== CONT TestIsValidCachePath/ls1532=== CONT TestParseSingleRange/none1533--- PASS: TestIsValidCachePath (0.00s)1534 --- PASS: TestIsValidCachePath/narinfo (0.00s)1535 --- PASS: TestIsValidCachePath/index.html (0.00s)1536 --- PASS: TestIsValidCachePath/short_hash (0.00s)1537 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1538 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1539 --- PASS: TestIsValidCachePath/empty (0.00s)1540 --- PASS: TestIsValidCachePath/random_path (0.00s)1541 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1542 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1543 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1544 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1545 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1546 --- PASS: TestIsValidCachePath/log (0.00s)1547 --- PASS: TestIsValidCachePath/realisation (0.00s)1548 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1549 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1550 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1551 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1552 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1553 --- PASS: TestIsValidCachePath/ls (0.00s)1554=== CONT TestParseSingleRange/open-ended1555=== CONT TestParseSingleRange/start_far_past_EOF1556=== CONT TestParseSingleRange/start_past_EOF1557=== CONT TestParseSingleRange/single_byte1558=== CONT TestParseSingleRange/suffix_exceeds_size1559=== CONT TestParseSingleRange/suffix1560=== CONT TestParseSingleRange/end_clamped_to_size1561=== CONT TestParseSingleRange/malformed_both_empty1562=== CONT TestParseSingleRange/closed1563=== CONT TestParseSingleRange/malformed_end_before_start1564=== CONT TestParseSingleRange/multi-range_ignored1565=== CONT TestParseSingleRange/malformed_no_dash1566=== CONT TestParseSingleRange/unknown_unit1567--- PASS: TestParseSingleRange (0.00s)1568 --- PASS: TestParseSingleRange/none (0.00s)1569 --- PASS: TestParseSingleRange/open-ended (0.00s)1570 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1571 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1572 --- PASS: TestParseSingleRange/single_byte (0.00s)1573 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1574 --- PASS: TestParseSingleRange/suffix (0.00s)1575 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1576 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1577 --- PASS: TestParseSingleRange/closed (0.00s)1578 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1579 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1580 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1581 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1582=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1583--- PASS: TestPushWaitsForSweepHoldingRow (0.96s)1584=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh15852026/10/10 19:42:28 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33333/oidc15862026/10/10 19:42:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15872026/10/10 19:42:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures15882026/10/10 19:42:28 INFO Garbage collection started15892026/10/10 19:42:28 INFO Aborted multipart uploads count=0 kept=015902026/10/10 19:42:28 WARN Force mode enabled - objects will be deleted immediately without grace period15912026/10/10 19:42:28 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=015922026/10/10 19:42:28 INFO Vacuumed table table=pending_closures15932026/10/10 19:42:28 INFO Vacuumed table table=pending_objects15942026/10/10 19:42:28 INFO Vacuumed table table=multipart_uploads15952026/10/10 19:42:28 INFO Vacuumed table table=closures15962026/10/10 19:42:28 INFO Received push request method=POST path=/api/pushes1597--- PASS: TestService_ReadAuthMiddleware (0.29s)1598=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart15992026/10/10 19:42:28 INFO Received complete multipart upload request method=POST path=/16002026/10/10 19:42:28 INFO Vacuumed table table=objects16012026/10/10 19:42:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16022026/10/10 19:42:28 INFO Uploading ls28aycl57pdmnnisbmwa1bpjy0vfr3c-ca-test (144B)16032026/10/10 19:42:28 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35727/oidc16042026/10/10 19:42:28 WARN Failed to register uploaded object key=ls28aycl57pdmnnisbmwa1bpjy0vfr3c.ls error="server returned 404: 404 page not found\n"16052026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16062026/10/10 19:42:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16072026/10/10 19:42:28 WARN Failed to register uploaded object key=log/ffy3skcb3rclhwpr63wm1g54v68qiikw-ca-test.drv error="server returned 404: 404 page not found\n"16082026/10/10 19:42:28 INFO Signed narinfos id=1 count=116092026/10/10 19:42:28 INFO Uploading 1 narinfos16102026/10/10 19:42:28 INFO Received complete push request method=POST path=/api/pushes/1/complete16112026/10/10 19:42:28 WARN Failed to register uploaded object key=ls28aycl57pdmnnisbmwa1bpjy0vfr3c.narinfo error="server returned 404: 404 page not found\n"16122026/10/10 19:42:28 INFO Completed push id=1 objects=4 duration=6.88736ms16132026/10/10 19:42:28 INFO Upload complete. (85ms)1614=== NAME TestClientCADerivations1615 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations3196708573/001/store/ls28aycl57pdmnnisbmwa1bpjy0vfr3c-ca-test1616 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1617 Compression: zstd1618 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1619 NarSize: 1441620 References: 1621 Deriver: /build/TestClientCADerivations3196708573/001/store/ffy3skcb3rclhwpr63wm1g54v68qiikw-ca-test.drv1622 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1623 client_ca_test.go:185: Checking for realisation files in S3...1624 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations16252026/10/10 19:42:28 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"1626 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache16272026/10/10 19:42:28 WARN mTLS auth: bound subjects configured but subject DN unavailable16282026/10/10 19:42:28 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1629--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.28s)1630=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16312026/10/10 19:42:28 INFO Received uploads request method=POST path=/1632=== NAME TestPinProtectsFromGC1633 client_integration_test.go:731: Pinned store path: /build/TestPinProtectsFromGC776523916/001/store/m8741lyvybzwryym21lpix1ibzlisrvm-pinned-file.txt1634 client_integration_test.go:732: Unpinned store path: /build/TestPinProtectsFromGC776523916/001/store/l2a8jfhvgmnrnmv7brpy2n16idd6iqyh-unpinned-file.txt1635--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.23s)1636=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16372026/10/10 19:42:28 INFO Received request for more parts method=POST path=/1638=== CONT TestPush_RejectsBadRequests/bad_root16392026/10/10 19:42:28 INFO Received push request method=POST path=/api/pushes1640=== CONT TestPush_RejectsBadRequests/no_roots16412026/10/10 19:42:28 INFO Received push request method=POST path=/api/pushes1642=== CONT TestPush_RejectsBadRequests/root_not_in_objects16432026/10/10 19:42:28 INFO Received push request method=POST path=/api/pushes1644=== CONT TestPush_RejectsBadRequests/no_objects16452026/10/10 19:42:28 INFO Received push request method=POST path=/api/pushes1646=== CONT TestServerTLSConfig/no_client_CA1647=== CONT TestServerTLSConfig/not_a_PEM_file1648--- PASS: TestPush_RejectsBadRequests (0.60s)1649 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1650 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1651 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1652 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1653=== CONT TestServerTLSConfig/missing_CA_file1654=== CONT TestPendingClosureWriteTimeout/empty1655=== CONT TestPendingClosureWriteTimeout/670k_objects1656=== CONT TestPendingClosureWriteTimeout/400_objects1657--- PASS: TestServerTLSConfig (0.00s)1658 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1659 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1660 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1661=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1662=== NAME TestClientWithDependencies1663 client_integration_test.go:613: Built derivation: /build/TestClientWithDependencies720707708/001/store/xqrskwqm41w6xshrhq7p74vgbmr1r7k3-test-script16642026/10/10 19:42:28 INFO Received push request method=POST path=/api/pushes16652026/10/10 19:42:28 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16662026/10/10 19:42:28 INFO Uploading 48i4mzr5g55c9yjgwpkmlyl8s66h25f6-shared-dep (136B)16672026/10/10 19:42:28 INFO Uploading 7kd4jzaycznvj6jpym0w40va85m76w5h-top (224B)1668--- PASS: TestObjectStatsLargeCommit (1.50s)1669=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16702026/10/10 19:42:28 INFO Received uploads request method=POST path=/1671=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16722026/10/10 19:42:28 INFO Received request for more parts method=POST path=/1673=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16742026/10/10 19:42:28 INFO Received complete multipart upload request method=POST path=/1675=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal16762026/10/10 19:42:28 INFO Received uploads request method=POST path=/1677--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1678 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1679 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1680 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1681 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1682=== CONT TestIsValidUploadKey/narinfo1683=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1684=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1685=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1686=== CONT TestIsValidUploadKey/index.html1687=== CONT TestIsValidUploadKey/nix-cache-info1688=== CONT TestIsValidUploadKey/realisation_plus_in_output1689=== CONT TestIsValidUploadKey/realisation1690=== CONT TestIsValidUploadKey/build_log_equals1691=== CONT TestIsValidUploadKey/build_log_question_mark1692=== CONT TestIsValidUploadKey/build_log_plus_in_name1693=== CONT TestIsValidUploadKey/nar_plain1694=== CONT TestIsValidUploadKey/traversal1695=== CONT TestIsValidUploadKey/nar_xz1696=== CONT TestIsValidUploadKey/listing1697=== CONT TestIsValidUploadKey/build_log_home-manager_file1698=== CONT TestIsValidUploadKey/nar_zst1699=== CONT TestIsValidUploadKey/build_log1700=== CONT TestIsValidUploadKey/empty_key1701=== CONT TestIsValidUploadKey/absolute1702=== CONT TestIsValidUploadKey/unknown_type1703=== CONT TestIsValidUploadKey/traversal_nar1704--- PASS: TestIsValidUploadKey (0.00s)1705 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1706 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1707 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1708 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1709 --- PASS: TestIsValidUploadKey/index.html (0.00s)1710 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1711 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1712 --- PASS: TestIsValidUploadKey/realisation (0.00s)1713 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1714 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1715 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1716 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1717 --- PASS: TestIsValidUploadKey/traversal (0.00s)1718 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1719 --- PASS: TestIsValidUploadKey/listing (0.00s)1720 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1721 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1722 --- PASS: TestIsValidUploadKey/build_log (0.00s)1723 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1724 --- PASS: TestIsValidUploadKey/absolute (0.00s)1725 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1726 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1727=== CONT TestGCEndsOnShutdown/before_the_run17282026/10/10 19:42:28 INFO Received uploads request method=POST path=/api/pending_closures17292026/10/10 19:42:28 INFO Received push request method=POST path=/api/pushes17302026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17312026/10/10 19:42:28 WARN Failed to register uploaded object key=48i4mzr5g55c9yjgwpkmlyl8s66h25f6.ls error="server returned 404: 404 page not found\n"17322026/10/10 19:42:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17332026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/0yagf6isimankif57w94k1shza7yqzvy2yp4rkx5hw09gaiza1ng.nar.zst error="server returned 404: 404 page not found\n"17342026/10/10 19:42:28 WARN Failed to register uploaded object key=7kd4jzaycznvj6jpym0w40va85m76w5h.ls error="server returned 404: 404 page not found\n"17352026/10/10 19:42:28 INFO Signed narinfos id=1 count=217362026/10/10 19:42:28 INFO Uploading 2 narinfos17372026/10/10 19:42:28 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17382026/10/10 19:42:28 INFO Uploading kxsi5z08xlchl1gbz7bb4dlpr1nsrdhm-b (216B)17392026/10/10 19:42:28 INFO Uploading kr740rpxcmx4hqrdmwffh2q2q2s11dlr-shared-dep (136B)17402026/10/10 19:42:28 INFO Received uploads request method=POST path=/api/pending_closures17412026/10/10 19:42:28 WARN Failed to register uploaded object key=48i4mzr5g55c9yjgwpkmlyl8s66h25f6.narinfo error="server returned 404: 404 page not found\n"17422026/10/10 19:42:28 INFO Received complete push request method=POST path=/api/pushes/1/complete17432026/10/10 19:42:28 WARN Failed to register uploaded object key=7kd4jzaycznvj6jpym0w40va85m76w5h.narinfo error="server returned 404: 404 page not found\n"17442026/10/10 19:42:28 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17452026/10/10 19:42:28 INFO Uploading 3ig448x13ahwncrll683xkg0idglvvnv-a (216B)17462026/10/10 19:42:28 INFO Uploading j5rnavfahs56c10g3cfvqp6d8slw8lb3-shared-dep (136B)17472026/10/10 19:42:28 WARN Failed to register uploaded object key=577gfkigr53w3f42767nsrr42iias33a.ls error="server returned 404: 404 page not found\n"17482026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17492026/10/10 19:42:28 WARN Failed to register uploaded object key=kxsi5z08xlchl1gbz7bb4dlpr1nsrdhm.ls error="server returned 404: 404 page not found\n"17502026/10/10 19:42:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17512026/10/10 19:42:28 WARN Failed to register uploaded object key=kr740rpxcmx4hqrdmwffh2q2q2s11dlr.ls error="server returned 404: 404 page not found\n"17522026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/1qm80sm84d40p063871mh8wwsmf055bl6zj483qmp6frkvwiwxz9.nar.zst error="server returned 404: 404 page not found\n"17532026/10/10 19:42:28 INFO Signed narinfos id=1 count=317542026/10/10 19:42:28 INFO Uploading 3 narinfos17552026/10/10 19:42:28 WARN Failed to register uploaded object key=15b8s0r27i00nfsn7742ywampl7whvpk.ls error="server returned 404: 404 page not found\n"17562026/10/10 19:42:28 WARN Failed to register uploaded object key=3ig448x13ahwncrll683xkg0idglvvnv.ls error="server returned 404: 404 page not found\n"17572026/10/10 19:42:28 WARN Failed to register uploaded object key=j5rnavfahs56c10g3cfvqp6d8slw8lb3.ls error="server returned 404: 404 page not found\n"17582026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17592026/10/10 19:42:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign17602026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/198ih580kcbbcp52cz8v676075zarpardqr39g10ikiihhm8kmfa.nar.zst error="server returned 404: 404 page not found\n"17612026/10/10 19:42:28 INFO Completed push id=1 objects=6 duration=6.081853ms17622026/10/10 19:42:28 INFO Upload complete. (60ms)17632026/10/10 19:42:28 INFO Signed narinfos id=2 count=217642026/10/10 19:42:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign17652026/10/10 19:42:28 INFO Signed narinfos id=1 count=217662026/10/10 19:42:28 INFO Uploading 4 narinfos1767=== NAME TestClientSharedPathCommittedMidPush17682026/10/10 19:42:28 INFO Received complete push request method=POST path=/api/pushes/1/complete1769 client_integration_test.go:680: Retrieved narinfo from S3:1770 StorePath: /build/TestClientSharedPathCommittedMidPush292864243/001/store/48i4mzr5g55c9yjgwpkmlyl8s66h25f6-shared-dep17712026/10/10 19:42:28 WARN Failed to register uploaded object key=577gfkigr53w3f42767nsrr42iias33a.narinfo error="server returned 404: 404 page not found\n"1772 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst17732026/10/10 19:42:28 WARN Failed to register uploaded object key=kxsi5z08xlchl1gbz7bb4dlpr1nsrdhm.narinfo error="server returned 404: 404 page not found\n"1774 Compression: zstd17752026/10/10 19:42:28 WARN Failed to register uploaded object key=kr740rpxcmx4hqrdmwffh2q2q2s11dlr.narinfo error="server returned 404: 404 page not found\n"1776 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821777 NarSize: 13617782026/10/10 19:42:28 INFO Received push request method=POST path=/api/pushes1779 References: 1780 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1781=== NAME TestClientWithDependencies1782 client_integration_test.go:615: Found 1 dependencies (including self)1783=== NAME TestClientSharedPathCommittedMidPush1784 client_integration_test.go:680: Retrieved narinfo from S3:1785 StorePath: /build/TestClientSharedPathCommittedMidPush292864243/001/store/7kd4jzaycznvj6jpym0w40va85m76w5h-top1786 URL: nar/0yagf6isimankif57w94k1shza7yqzvy2yp4rkx5hw09gaiza1ng.nar.zst1787 Compression: zstd1788 NarHash: sha256:0yagf6isimankif57w94k1shza7yqzvy2yp4rkx5hw09gaiza1ng1789 NarSize: 2241790 References: /build/TestClientSharedPathCommittedMidPush292864243/001/store/48i4mzr5g55c9yjgwpkmlyl8s66h25f6-shared-dep1791 CA: text:sha256:1qrv0i9gh53azid7mdbd7q0zfhyjlyp15xkkcqrnggghg6bw5j7617922026/10/10 19:42:28 WARN Failed to register uploaded object key=j5rnavfahs56c10g3cfvqp6d8slw8lb3.narinfo error="server returned 404: 404 page not found\n"17932026/10/10 19:42:28 WARN Failed to register uploaded object key=3ig448x13ahwncrll683xkg0idglvvnv.narinfo error="server returned 404: 404 page not found\n"17942026/10/10 19:42:28 WARN Failed to register uploaded object key=15b8s0r27i00nfsn7742ywampl7whvpk.narinfo error="server returned 404: 404 page not found\n"17952026/10/10 19:42:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17962026/10/10 19:42:28 INFO Uploading m8741lyvybzwryym21lpix1ibzlisrvm-pinned-file.txt (128B)17972026/10/10 19:42:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17982026/10/10 19:42:28 WARN Failed to register uploaded object key=j5rnavfahs56c10g3cfvqp6d8slw8lb3.narinfo error="server returned 404: 404 page not found\n"17992026/10/10 19:42:28 INFO Completed push id=1 objects=8 duration=5.890551ms18002026/10/10 19:42:28 INFO Upload complete. (61ms)1801=== NAME TestClientPushesUseOnePush1802 client_pushes_test.go:97: Retrieved narinfo from S3:1803 StorePath: /build/TestClientPushesUseOnePush2456628547/001/store/kr740rpxcmx4hqrdmwffh2q2q2s11dlr-shared-dep1804 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1805 Compression: zstd1806 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821807 NarSize: 1361808 References: 1809 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1810--- PASS: TestClientSharedPathCommittedMidPush (0.45s)1811=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1812--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.60s)1813=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete18142026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"18152026/10/10 19:42:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18162026/10/10 19:42:28 WARN Failed to register uploaded object key=m8741lyvybzwryym21lpix1ibzlisrvm.ls error="server returned 404: 404 page not found\n"18172026/10/10 19:42:28 INFO Signed narinfos id=1 count=118182026/10/10 19:42:28 INFO Uploading 1 narinfos1819=== NAME TestClientPushesUseOnePush1820 client_pushes_test.go:97: Retrieved narinfo from S3:1821 StorePath: /build/TestClientPushesUseOnePush2456628547/001/store/577gfkigr53w3f42767nsrr42iias33a-a1822 URL: nar/1qm80sm84d40p063871mh8wwsmf055bl6zj483qmp6frkvwiwxz9.nar.zst1823 Compression: zstd1824 NarHash: sha256:1qm80sm84d40p063871mh8wwsmf055bl6zj483qmp6frkvwiwxz91825 NarSize: 2161826 References: /build/TestClientPushesUseOnePush2456628547/001/store/kr740rpxcmx4hqrdmwffh2q2q2s11dlr-shared-dep1827 CA: text:sha256:1bq8r56ixdrywbklczvasixfk75fhixyawk183smcs15yvlxg66s18282026/10/10 19:42:28 INFO Completed upload id=1 objects=6 duration=6.530417ms18292026/10/10 19:42:28 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete1830 client_pushes_test.go:97: Retrieved narinfo from S3:1831 StorePath: /build/TestClientPushesUseOnePush2456628547/001/store/kxsi5z08xlchl1gbz7bb4dlpr1nsrdhm-b1832 URL: nar/1qm80sm84d40p063871mh8wwsmf055bl6zj483qmp6frkvwiwxz9.nar.zst1833 Compression: zstd1834 NarHash: sha256:1qm80sm84d40p063871mh8wwsmf055bl6zj483qmp6frkvwiwxz91835 NarSize: 2161836 References: /build/TestClientPushesUseOnePush2456628547/001/store/kr740rpxcmx4hqrdmwffh2q2q2s11dlr-shared-dep1837 CA: text:sha256:1bq8r56ixdrywbklczvasixfk75fhixyawk183smcs15yvlxg66s18382026/10/10 19:42:28 INFO Received complete push request method=POST path=/api/pushes/1/complete18392026/10/10 19:42:28 WARN Failed to register uploaded object key=m8741lyvybzwryym21lpix1ibzlisrvm.narinfo error="server returned 404: 404 page not found\n"1840=== NAME TestClientCADerivations1841 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1842 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1843 error: binary cache 's3://bucket76?endpoint=http://localhost:46865®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations3196708573/001/store'1844 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11845=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1846--- PASS: TestClientPushesUseOnePush (0.52s)1847=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18482026/10/10 19:42:28 INFO Completed upload id=2 objects=6 duration=5.856651ms18492026/10/10 19:42:28 INFO Upload complete. (74ms)1850--- PASS: TestClientCADerivations (0.64s)1851=== CONT TestClientErrorHandling/InvalidStorePath18522026/10/10 19:42:28 INFO Completed push id=1 objects=3 duration=5.776131ms1853=== NAME TestClientFallsBackToClosures1854 client_pushes_test.go:112: Retrieved narinfo from S3:1855 StorePath: /build/TestClientFallsBackToClosures2047317882/001/store/j5rnavfahs56c10g3cfvqp6d8slw8lb3-shared-dep18562026/10/10 19:42:28 INFO Upload complete. (60ms)1857 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1858 Compression: zstd1859 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821860 NarSize: 1361861 References: 1862 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1863 client_pushes_test.go:112: Retrieved narinfo from S3:1864 StorePath: /build/TestClientFallsBackToClosures2047317882/001/store/3ig448x13ahwncrll683xkg0idglvvnv-a1865 URL: nar/198ih580kcbbcp52cz8v676075zarpardqr39g10ikiihhm8kmfa.nar.zst1866 Compression: zstd1867 NarHash: sha256:198ih580kcbbcp52cz8v676075zarpardqr39g10ikiihhm8kmfa1868 NarSize: 2161869 References: /build/TestClientFallsBackToClosures2047317882/001/store/j5rnavfahs56c10g3cfvqp6d8slw8lb3-shared-dep1870 CA: text:sha256:0z815rf7j4bdpnbbbjwmnvcpqw4lw3skw0r20vkph36b9ys5zhz51871=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1872=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1873=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1874=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1875=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1876=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1877=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1878=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1879=== CONT TestClientErrorHandling/InvalidAuthToken1880=== NAME TestClientFallsBackToClosures1881 client_pushes_test.go:112: Retrieved narinfo from S3:1882 StorePath: /build/TestClientFallsBackToClosures2047317882/001/store/15b8s0r27i00nfsn7742ywampl7whvpk-b1883 URL: nar/198ih580kcbbcp52cz8v676075zarpardqr39g10ikiihhm8kmfa.nar.zst1884 Compression: zstd1885 NarHash: sha256:198ih580kcbbcp52cz8v676075zarpardqr39g10ikiihhm8kmfa1886 NarSize: 2161887 References: /build/TestClientFallsBackToClosures2047317882/001/store/j5rnavfahs56c10g3cfvqp6d8slw8lb3-shared-dep1888 CA: text:sha256:0z815rf7j4bdpnbbbjwmnvcpqw4lw3skw0r20vkph36b9ys5zhz51889--- PASS: TestClientFallsBackToClosures (0.57s)1890=== CONT TestClientErrorHandling/ServerNotAvailable18912026/10/10 19:42:28 INFO Received push request method=POST path=/api/pushes1892=== RUN TestService_RequireScope_OIDC/builder_may_write1893=== PAUSE TestService_RequireScope_OIDC/builder_may_write1894=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1895=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1896=== RUN TestService_RequireScope_OIDC/ops_may_admin1897=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1898=== RUN TestService_RequireScope_OIDC/ops_may_not_write1899=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1900=== RUN TestService_RequireScope_OIDC/reader_may_not_write1901=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1902=== RUN TestService_RequireScope_OIDC/static_token_may_admin1903=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1904=== RUN TestService_RequireScope_OIDC/static_token_may_write1905=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1906=== RUN TestService_RequireScope_OIDC/reader_may_read1907=== PAUSE TestService_RequireScope_OIDC/reader_may_read1908=== RUN TestService_RequireScope_OIDC/writer_implies_read1909=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1910=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1911=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1912=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1913=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1914=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1915=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1916=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1917=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1918=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1919=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1920=== CONT TestResolveDBConnectionString/flag_wins1921=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1922=== CONT TestResolveDBConnectionString/missing_file_is_an_error1923=== CONT TestResolveDBConnectionString/file_when_flag_empty1924=== CONT TestResolveDBConnectionString/nothing_configured1925--- PASS: TestResolveDBConnectionString (0.00s)1926 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1927 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1928 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1929 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1930 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1931=== CONT TestCacheConfigHandler/full_config,_no_issuer1932=== CONT TestCacheConfigHandler/no_signing_keys1933=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1934=== CONT TestCacheConfigHandler/no_cache_url_configured1935--- PASS: TestCacheConfigHandler (0.00s)1936 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1937 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1938 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1939 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1940=== CONT TestProxyWriteTimeout/narinfo1941=== CONT TestProxyWriteTimeout/10_GiB_nar1942=== CONT TestProxyWriteTimeout/unknown_size1943=== CONT TestProxyWriteTimeout/1_GiB_nar1944--- PASS: TestProxyWriteTimeout (0.00s)1945 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1946 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1947 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1948 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1949=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1950=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19512026/10/10 19:42:28 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]1952=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19532026/10/10 19:42:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19542026/10/10 19:42:28 INFO Uploading xqrskwqm41w6xshrhq7p74vgbmr1r7k3-test-script (136B)19552026/10/10 19:42:28 WARN Authentication failed token_preview=eyJhbGciOi...VIFwE_tcXg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1956=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token19572026/10/10 19:42:28 WARN Failed to register uploaded object key=xqrskwqm41w6xshrhq7p74vgbmr1r7k3.ls error="server returned 404: 404 page not found\n"19582026/10/10 19:42:28 WARN Failed to register uploaded object key=log/nsb6hqf34pw057b19kqa71r4m34x6xnd-test-script.drv error="server returned 404: 404 page not found\n"19592026/10/10 19:42:28 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19602026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"1961=== CONT TestService_RequireScope_OIDC/builder_may_write1962--- PASS: TestService_AuthMiddleware_OIDC (0.38s)1963 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1964 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1965 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1966 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)19672026/10/10 19:42:28 INFO Signed narinfos id=1 count=119682026/10/10 19:42:28 INFO Uploading 1 narinfos1969=== CONT TestService_RequireScope_OIDC/reader_may_read1970=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1971=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19722026/10/10 19:42:28 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]1973=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1974=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1975=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1976=== CONT TestService_RequireScope_OIDC/writer_implies_read1977=== CONT TestService_RequireScope_OIDC/reader_may_not_write1978=== CONT TestService_RequireScope_OIDC/static_token_may_write1979=== CONT TestService_RequireScope_OIDC/static_token_may_admin1980=== CONT TestService_RequireScope_OIDC/ops_may_admin1981=== CONT TestService_RequireScope_OIDC/ops_may_not_write1982=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1983--- PASS: TestService_RequireScope_OIDC (0.33s)1984 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1985 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1986 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1987 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1988 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1989 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1990 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1991 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1992 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1993 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1994 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)1995 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1996 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1997 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)19982026/10/10 19:42:28 INFO Received complete push request method=POST path=/api/pushes/1/complete19992026/10/10 19:42:28 WARN Failed to register uploaded object key=xqrskwqm41w6xshrhq7p74vgbmr1r7k3.narinfo error="server returned 404: 404 page not found\n"20002026/10/10 19:42:28 INFO Received push request method=POST path=/api/pushes20012026/10/10 19:42:28 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20022026/10/10 19:42:28 INFO Uploading l2a8jfhvgmnrnmv7brpy2n16idd6iqyh-unpinned-file.txt (128B)20032026/10/10 19:42:28 INFO Completed push id=1 objects=4 duration=6.769998ms20042026/10/10 19:42:28 INFO Upload complete. (61ms)20052026/10/10 19:42:28 WARN Failed to register uploaded object key=l2a8jfhvgmnrnmv7brpy2n16idd6iqyh.ls error="server returned 404: 404 page not found\n"20062026/10/10 19:42:28 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign20072026/10/10 19:42:28 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"20082026/10/10 19:42:28 INFO Signed narinfos id=2 count=120092026/10/10 19:42:28 INFO Uploading 1 narinfos2010=== NAME TestClientWithDependencies2011 client_integration_test.go:617: Skipping nix copy test - isolated store (/build/TestClientWithDependencies720707708/001/store) requires matching store prefix20122026/10/10 19:42:28 INFO Received complete push request method=POST path=/api/pushes/2/complete20132026/10/10 19:42:28 WARN Failed to register uploaded object key=l2a8jfhvgmnrnmv7brpy2n16idd6iqyh.narinfo error="server returned 404: 404 page not found\n"20142026/10/10 19:42:28 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/present2015--- PASS: TestClientWithDependencies (0.53s)20162026/10/10 19:42:28 INFO Completed push id=2 objects=3 duration=1.689895ms20172026/10/10 19:42:28 INFO Upload complete. (48ms)20182026/10/10 19:42:28 INFO Received uploads request method=POST path=/api/pending_closures20192026/10/10 19:42:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures20202026/10/10 19:42:28 INFO Garbage collection started20212026/10/10 19:42:28 INFO Aborted multipart uploads count=0 kept=020222026/10/10 19:42:28 WARN Force mode enabled - objects will be deleted immediately without grace period20232026/10/10 19:42:28 INFO Aborted multipart uploads count=0 kept=020242026/10/10 19:42:28 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=020252026/10/10 19:42:28 WARN Force mode enabled - objects will be deleted immediately without grace period20262026/10/10 19:42:28 INFO Vacuumed table table=pending_closures20272026/10/10 19:42:28 INFO Vacuumed table table=pending_objects20282026/10/10 19:42:28 INFO Vacuumed table table=multipart_uploads20292026/10/10 19:42:28 INFO Vacuumed table table=closures20302026/10/10 19:42:28 INFO Received uploads request method=POST path=/api/pending_closures20312026/10/10 19:42:28 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:46865/bucket95/?delete=\": context canceled"20322026/10/10 19:42:28 INFO Vacuumed table table=objects20332026/10/10 19:42:28 INFO Aborted multipart uploads count=0 kept=020342026/10/10 19:42:28 INFO lead: released remote=192.0.2.1:12342035--- PASS: TestLeadEndsOnShutdown (1.53s)20362026/10/10 19:42:28 WARN Force mode enabled - objects will be deleted immediately without grace period20372026/10/10 19:42:28 WARN Request failed, retrying attempt=2 backoff=210.69387ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20382026/10/10 19:42:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=020392026/10/10 19:42:28 INFO Vacuumed table table=pending_closures20402026/10/10 19:42:28 INFO Vacuumed table table=pending_objects20412026/10/10 19:42:28 INFO Vacuumed table table=multipart_uploads20422026/10/10 19:42:28 INFO Vacuumed table table=closures20432026/10/10 19:42:28 INFO Vacuumed table table=objects20442026/10/10 19:42:28 INFO Aborted multipart uploads count=0 kept=020452026/10/10 19:42:28 WARN Force mode enabled - objects will be deleted immediately without grace period20462026/10/10 19:42:28 INFO Received uploads request method=POST path=/api/pending_closures2047--- PASS: TestGCEndsOnShutdown (0.00s)2048 --- PASS: TestGCEndsOnShutdown/before_the_run (0.16s)2049 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.17s)2050 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.23s)20512026/10/10 19:42:28 INFO Aborted multipart uploads count=0 kept=020522026/10/10 19:42:28 WARN Force mode enabled - objects will be deleted immediately without grace period20532026/10/10 19:42:28 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020542026/10/10 19:42:28 INFO Vacuumed table table=pending_closures20552026/10/10 19:42:28 INFO Vacuumed table table=pending_objects20562026/10/10 19:42:28 INFO Vacuumed table table=multipart_uploads20572026/10/10 19:42:28 INFO Vacuumed table table=closures20582026/10/10 19:42:28 INFO Vacuumed table table=objects2059--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2060 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.21s)2061 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.26s)20622026/10/10 19:42:28 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"20632026/10/10 19:42:28 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"2064=== NAME TestOrphanedObjectsGCStressTest2065 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2066 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion20672026/10/10 19:42:29 WARN Request failed, retrying attempt=3 backoff=414.782559ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2068--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2069 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.68s)2070 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.69s)2071=== NAME TestOrphanedObjectsGCStressTest2072 orphaned_objects_gc_test.go:503: Stress test completed successfully:2073 orphaned_objects_gc_test.go:504: - Active objects preserved: 202074 orphaned_objects_gc_test.go:505: - Objects deleted: 2102075 orphaned_objects_gc_test.go:506: - Total GC'd: 2102076--- PASS: TestOrphanedObjectsGCStressTest (2.16s)20772026/10/10 19:42:29 WARN Request failed, retrying attempt=4 backoff=821.392642ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20782026/10/10 19:42:29 INFO lead: released remote=192.0.2.1:12342079--- PASS: TestUploadHandlersRejectOversizedBody (0.15s)2080 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.05s)2081 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)2082 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.97s)2083--- PASS: TestPendingClosureWriteTimeout (0.00s)2084 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2085 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2086 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2087 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (0.96s)20882026/10/10 19:42:29 INFO lead: acquired remote=192.0.2.1:12342089--- PASS: TestDeleteClosuresRacingPins (1.51s)20902026/10/10 19:42:30 WARN Request failed, retrying attempt=5 backoff=1.673592638s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20912026/10/10 19:42:30 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02092=== NAME TestClientIntegration2093 client_integration_test.go:323: Objects in database after GC:2094 client_integration_test.go:323: Successfully deleted all objects with GC --force2095--- PASS: TestClientIntegration (2.55s)20962026/10/10 19:42:30 INFO lead: released remote=192.0.2.1:12342097--- PASS: TestLeadElectsOneAndHandsOver (2.68s)20982026/10/10 19:42:30 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020992026/10/10 19:42:30 INFO Received create pin request method=POST path=/api/pins/myapp21002026/10/10 19:42:30 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC776523916/001/store/m8741lyvybzwryym21lpix1ibzlisrvm-pinned-file.txt narinfo_key=m8741lyvybzwryym21lpix1ibzlisrvm.narinfo21012026/10/10 19:42:30 INFO Starting cleanup of old closures method=DELETE path=/api/closures21022026/10/10 19:42:30 INFO Garbage collection started21032026/10/10 19:42:30 INFO Aborted multipart uploads count=0 kept=021042026/10/10 19:42:30 WARN Force mode enabled - objects will be deleted immediately without grace period21052026/10/10 19:42:30 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021062026/10/10 19:42:30 INFO Vacuumed table table=pending_closures21072026/10/10 19:42:30 INFO Vacuumed table table=pending_objects21082026/10/10 19:42:30 INFO Vacuumed table table=multipart_uploads21092026/10/10 19:42:30 INFO Vacuumed table table=closures21102026/10/10 19:42:30 INFO Vacuumed table table=objects2111--- PASS: TestReadProxyOutlastsServerWriteTimeout (5.07s)21122026/10/10 19:42:31 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-config21132026/10/10 19:42:32 WARN Request failed, retrying attempt=2 backoff=201.224852ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21142026/10/10 19:42:32 WARN Rate limiter enabled after throttle name=s3-test rate=521152026/10/10 19:42:32 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2116=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2117 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102118 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002119--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (4.23s)21202026/10/10 19:42:32 WARN Request failed, retrying attempt=3 backoff=387.717434ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21212026/10/10 19:42:32 WARN Request failed, retrying attempt=4 backoff=795.079938ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2122=== NAME TestPinProtectsFromGC2123 client_integration_test.go:840: Pin successfully protected closure from garbage collection2124--- PASS: TestPinProtectsFromGC (4.59s)2125--- PASS: TestConnectWaitsForAPeerMigration (5.13s)21262026/10/10 19:42:33 WARN Request failed, retrying attempt=5 backoff=1.564568681s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21272026/10/10 19:42:33 INFO Aborted multipart uploads count=1 kept=021282026/10/10 19:42:33 INFO Received cleanup request method=DELETE path=/api/pending_closures21292026/10/10 19:42:33 INFO Aborted multipart uploads count=1 kept=02130--- PASS: TestPendingCleanupUsesOneCutoff (6.52s)21312026/10/10 19:42:35 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"21322026/10/10 19:42:35 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-config21332026/10/10 19:42:35 WARN Request failed, retrying attempt=2 backoff=181.171133ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21342026/10/10 19:42:35 WARN Request failed, retrying attempt=3 backoff=424.982852ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21352026/10/10 19:42:35 WARN Request failed, retrying attempt=4 backoff=793.614746ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21362026/10/10 19:42:36 WARN Request failed, retrying attempt=5 backoff=1.632017126s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21372026/10/10 19:42:38 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_closures21382026/10/10 19:42:38 WARN Request failed, retrying attempt=2 backoff=204.691934ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21392026/10/10 19:42:38 WARN Request failed, retrying attempt=3 backoff=420.539988ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21402026/10/10 19:42:38 WARN Request failed, retrying attempt=4 backoff=741.830862ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21412026/10/10 19:42:39 WARN Request failed, retrying attempt=5 backoff=1.73123029s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2142--- PASS: TestClientErrorHandling (0.00s)2143 --- PASS: TestClientErrorHandling/InvalidStorePath (0.26s)2144 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.29s)2145 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.73s)2146PASS2147{"timestamp":"2026-10-10T19:42:41.384520943Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51298","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2354,"threadName":"rustfs-worker","threadId":"ThreadId(202)"}21482026-10-10 19:42:41.623 UTC [127] LOG: received smart shutdown request21492026-10-10 19:42:41.627 UTC [127] LOG: background worker "logical replication launcher" (PID 137) exited with exit code 121502026-10-10 19:42:41.640 UTC [132] LOG: shutting down21512026-10-10 19:42:41.640 UTC [132] LOG: checkpoint starting: shutdown immediate21522026-10-10 19:42:42.463 UTC [132] LOG: checkpoint complete: wrote 10785 buffers (65.8%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.171 s, sync=0.619 s, total=0.824 s; sync files=34045, longest=0.012 s, average=0.001 s; distance=531576 kB, estimate=531576 kB; lsn=0/21E83F40, redo lsn=0/21E83F4021532026-10-10 19:42:42.543 UTC [127] LOG: database system is shut down2154Running OIDC tests...2155=== RUN TestAudienceForIssuer2156=== PAUSE TestAudienceForIssuer2157=== RUN TestGlobMatch2158=== PAUSE TestGlobMatch2159=== RUN TestValidateToken_ValidToken2160=== PAUSE TestValidateToken_ValidToken2161=== RUN TestValidateToken_WrongAudience2162=== PAUSE TestValidateToken_WrongAudience2163=== RUN TestValidateToken_Expired2164=== PAUSE TestValidateToken_Expired2165=== RUN TestValidateToken_BoundClaimsMismatch2166=== PAUSE TestValidateToken_BoundClaimsMismatch2167=== RUN TestValidateToken_BoundSubjectMismatch2168=== PAUSE TestValidateToken_BoundSubjectMismatch2169=== RUN TestValidateToken_MultipleProviders2170=== PAUSE TestValidateToken_MultipleProviders2171=== RUN TestValidateToken_NoMatchingProvider2172=== PAUSE TestValidateToken_NoMatchingProvider2173=== RUN TestValidateToken_KubernetesServiceAccount2174=== PAUSE TestValidateToken_KubernetesServiceAccount2175=== RUN TestNewValidator_KubernetesRequiresCA2176=== PAUSE TestNewValidator_KubernetesRequiresCA2177=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2178=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2179=== RUN TestPins_ReservedForMatchingRule2180=== PAUSE TestPins_ReservedForMatchingRule2181=== RUN TestPins_TopLevelShorthand2182=== PAUSE TestPins_TopLevelShorthand2183=== RUN TestPins_ConfigValidation2184=== PAUSE TestPins_ConfigValidation2185=== RUN TestScopes_LegacyProviderDefaultsToWrite2186=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2187=== RUN TestScopes_Rules2188=== PAUSE TestScopes_Rules2189=== RUN TestScopes_ConfigValidation2190=== PAUSE TestScopes_ConfigValidation2191=== CONT TestAudienceForIssuer2192=== CONT TestValidateToken_BoundClaimsMismatch2193=== CONT TestValidateToken_MultipleProviders2194--- PASS: TestAudienceForIssuer (0.00s)2195=== CONT TestValidateToken_KubernetesServiceAccount2196=== CONT TestScopes_LegacyProviderDefaultsToWrite2197=== CONT TestValidateToken_WrongAudience2198=== CONT TestValidateToken_Expired2199=== CONT TestPins_TopLevelShorthand2200=== CONT TestValidateToken_ValidToken2201=== CONT TestPins_ReservedForMatchingRule2202=== CONT TestScopes_Rules2203=== CONT TestGlobMatch2204=== RUN TestGlobMatch/foo_foo2205=== PAUSE TestGlobMatch/foo_foo2206=== RUN TestGlobMatch/foo_bar2207=== PAUSE TestGlobMatch/foo_bar2208=== RUN TestGlobMatch/*_2209=== PAUSE TestGlobMatch/*_2210=== RUN TestGlobMatch/*_anything2211=== PAUSE TestGlobMatch/*_anything2212=== RUN TestGlobMatch/foo*_foo2213=== PAUSE TestGlobMatch/foo*_foo2214=== RUN TestGlobMatch/foo*_foobar2215=== CONT TestScopes_ConfigValidation2216=== CONT TestNewValidator_KubernetesRequiresCA2217=== CONT TestValidateToken_NoMatchingProvider2218=== CONT TestValidateToken_BoundSubjectMismatch2219=== CONT TestPins_ConfigValidation2220=== PAUSE TestGlobMatch/foo*_foobar2221=== RUN TestGlobMatch/foo*_bar2222=== PAUSE TestGlobMatch/foo*_bar2223=== RUN TestGlobMatch/*bar_bar2224=== PAUSE TestGlobMatch/*bar_bar2225=== RUN TestGlobMatch/*bar_foobar2226=== PAUSE TestGlobMatch/*bar_foobar2227=== RUN TestGlobMatch/*bar_foo2228=== PAUSE TestGlobMatch/*bar_foo2229=== RUN TestGlobMatch/foo*bar_foobar2230=== PAUSE TestGlobMatch/foo*bar_foobar2231=== RUN TestGlobMatch/foo*bar_foo123bar2232=== PAUSE TestGlobMatch/foo*bar_foo123bar2233=== RUN TestGlobMatch/foo*bar_foobarbaz2234=== PAUSE TestGlobMatch/foo*bar_foobarbaz2235=== RUN TestGlobMatch/*/*_foo/bar2236=== PAUSE TestGlobMatch/*/*_foo/bar2237=== RUN TestGlobMatch/*/*_foo2238=== PAUSE TestGlobMatch/*/*_foo2239=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2240=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2241=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02242=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02243=== RUN TestGlobMatch/refs/*/main_refs/heads/main2244=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2245=== RUN TestGlobMatch/fo?_foo2246=== PAUSE TestGlobMatch/fo?_foo2247=== RUN TestGlobMatch/fo?_fo2248=== PAUSE TestGlobMatch/fo?_fo2249=== RUN TestGlobMatch/fo?_fooo2250=== PAUSE TestGlobMatch/fo?_fooo2251=== RUN TestGlobMatch/?oo_foo2252=== PAUSE TestGlobMatch/?oo_foo2253=== RUN TestGlobMatch/?oo_boo2254=== PAUSE TestGlobMatch/?oo_boo2255=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2256=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2257=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2258=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2259=== CONT TestGlobMatch/foo_foo2260=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2261=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2262=== CONT TestGlobMatch/?oo_boo2263=== CONT TestGlobMatch/?oo_foo2264=== CONT TestGlobMatch/fo?_fooo2265=== CONT TestGlobMatch/fo?_fo2266=== CONT TestGlobMatch/fo?_foo2267=== CONT TestGlobMatch/refs/*/main_refs/heads/main2268=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02269=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2270=== CONT TestGlobMatch/*/*_foo2271=== CONT TestGlobMatch/*/*_foo/bar2272=== CONT TestGlobMatch/foo*bar_foobarbaz2273=== CONT TestGlobMatch/foo*bar_foo123bar2274=== CONT TestGlobMatch/foo*bar_foobar2275=== CONT TestGlobMatch/*bar_foo2276=== CONT TestGlobMatch/*bar_foobar2277=== CONT TestGlobMatch/*bar_bar2278=== CONT TestGlobMatch/foo*_bar2279=== CONT TestGlobMatch/foo*_foobar2280=== CONT TestGlobMatch/foo*_foo2281=== CONT TestGlobMatch/*_anything2282=== CONT TestGlobMatch/*_2283=== CONT TestGlobMatch/foo_bar2284--- PASS: TestGlobMatch (0.00s)2285 --- PASS: TestGlobMatch/foo_foo (0.00s)2286 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2287 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2288 --- PASS: TestGlobMatch/?oo_boo (0.00s)2289 --- PASS: TestGlobMatch/?oo_foo (0.00s)2290 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2291 --- PASS: TestGlobMatch/fo?_fo (0.00s)2292 --- PASS: TestGlobMatch/fo?_foo (0.00s)2293 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2294 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2295 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2296 --- PASS: TestGlobMatch/*/*_foo (0.00s)2297 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2298 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2299 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2300 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2301 --- PASS: TestGlobMatch/*bar_foo (0.00s)2302 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2303 --- PASS: TestGlobMatch/*bar_bar (0.00s)2304 --- PASS: TestGlobMatch/foo*_bar (0.00s)2305 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2306 --- PASS: TestGlobMatch/foo*_foo (0.00s)2307 --- PASS: TestGlobMatch/*_anything (0.00s)2308 --- PASS: TestGlobMatch/*_ (0.00s)2309 --- PASS: TestGlobMatch/foo_bar (0.00s)2310=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2311--- PASS: TestPins_ConfigValidation (0.00s)2312--- PASS: TestScopes_ConfigValidation (0.00s)23132026/10/10 19:42:44 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232314--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.06s)23152026/10/10 19:42:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37693/oidc2316--- PASS: TestValidateToken_WrongAudience (0.07s)23172026/10/10 19:42:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37391/oidc23182026/10/10 19:42:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40979/oidc2319--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.10s)2320--- PASS: TestValidateToken_BoundSubjectMismatch (0.09s)23212026/10/10 19:42:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43669/oidc2322--- PASS: TestValidateToken_ValidToken (0.12s)23232026/10/10 19:42:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43045/oidc2324--- PASS: TestPins_TopLevelShorthand (0.13s)23252026/10/10 19:42:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:38929/oidc23262026/10/10 19:42:44 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:39237/oidc2327--- PASS: TestValidateToken_MultipleProviders (0.14s)23282026/10/10 19:42:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40249/oidc2329--- PASS: TestValidateToken_Expired (0.14s)23302026/10/10 19:42:44 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:466412331--- PASS: TestValidateToken_KubernetesServiceAccount (0.15s)23322026/10/10 19:42:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35967/oidc2333--- PASS: TestPins_ReservedForMatchingRule (0.19s)23342026/10/10 19:42:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:39551/oidc2335--- PASS: TestValidateToken_NoMatchingProvider (0.21s)23362026/10/10 19:42:44 http: TLS handshake error from 127.0.0.1:51530: remote error: tls: bad certificate2337--- PASS: TestNewValidator_KubernetesRequiresCA (0.23s)23382026/10/10 19:42:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42991/oidc2339--- PASS: TestScopes_Rules (0.24s)23402026/10/10 19:42:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:40797/oidc2341--- PASS: TestValidateToken_BoundClaimsMismatch (0.33s)2342PASS2343Running hook tests...2344=== RUN TestSendPathsEmpty2345=== PAUSE TestSendPathsEmpty2346=== RUN TestQueueEnqueueAndFetch2347=== PAUSE TestQueueEnqueueAndFetch2348=== RUN TestQueueDeduplication2349=== PAUSE TestQueueDeduplication2350=== RUN TestQueueRemove2351=== PAUSE TestQueueRemove2352=== RUN TestQueueFetchBatchLimit2353=== PAUSE TestQueueFetchBatchLimit2354=== RUN TestQueueRetryMovesToBack2355=== PAUSE TestQueueRetryMovesToBack2356=== RUN TestQueueFetchRemoveLifecycle2357=== PAUSE TestQueueFetchRemoveLifecycle2358=== RUN TestQueueConcurrentWriters2359=== PAUSE TestQueueConcurrentWriters2360=== RUN TestQueueRemoveLargeClosure2361=== PAUSE TestQueueRemoveLargeClosure2362=== RUN TestServerClientIntegration2363--- PASS: TestServerClientIntegration (0.00s)2364=== RUN TestServerQueueError23652026/10/10 19:42:44 ERROR Failed to queue paths error="permission denied" count=12366--- PASS: TestServerQueueError (0.00s)2367=== RUN TestGetListenerSocketActivation2368 server_test.go:219: === RUN TestGetListenerSocketActivation2369 --- PASS: TestGetListenerSocketActivation (0.00s)2370 PASS2371 2372--- PASS: TestGetListenerSocketActivation (0.01s)2373=== RUN TestDrainIsolatesPoisonPath2374=== PAUSE TestDrainIsolatesPoisonPath2375=== RUN TestRunNotBlockedByPoisonHead2376=== PAUSE TestRunNotBlockedByPoisonHead2377=== RUN TestDrainGivesUpWhenServerDown2378=== PAUSE TestDrainGivesUpWhenServerDown2379=== RUN TestFailedPathPrunedByLaterClosure2380=== PAUSE TestFailedPathPrunedByLaterClosure2381=== RUN TestWorkerUploadsAndRemoves2382=== PAUSE TestWorkerUploadsAndRemoves2383=== RUN TestWorkerSkipsGCdPaths2384=== PAUSE TestWorkerSkipsGCdPaths2385=== RUN TestWorkerPrunesClosureDeps2386=== PAUSE TestWorkerPrunesClosureDeps2387=== RUN TestDrainTimeout2388=== PAUSE TestDrainTimeout2389=== CONT TestSendPathsEmpty2390=== CONT TestWorkerUploadsAndRemoves2391--- PASS: TestSendPathsEmpty (0.00s)2392=== CONT TestDrainTimeout2393=== CONT TestQueueRemoveLargeClosure2394=== CONT TestWorkerSkipsGCdPaths2395=== CONT TestWorkerPrunesClosureDeps2396=== CONT TestQueueConcurrentWriters2397=== CONT TestDrainGivesUpWhenServerDown2398=== CONT TestQueueFetchRemoveLifecycle2399=== CONT TestFailedPathPrunedByLaterClosure2400=== CONT TestQueueRetryMovesToBack2401=== CONT TestQueueFetchBatchLimit2402=== CONT TestQueueDeduplication2403=== CONT TestQueueEnqueueAndFetch2404=== CONT TestQueueRemove2405=== CONT TestDrainIsolatesPoisonPath2406=== CONT TestRunNotBlockedByPoisonHead24072026/10/10 19:42:44 INFO Upload queue status pending=324082026/10/10 19:42:44 INFO Uploading batch count=124092026/10/10 19:42:44 INFO Upload queue status pending=224102026/10/10 19:42:44 INFO Uploading batch count=224112026/10/10 19:42:44 ERROR Upload failed error="upload failed" count=124122026/10/10 19:42:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths191346625/002/nonexistent24132026/10/10 19:42:44 INFO Uploading batch count=124142026/10/10 19:42:44 ERROR Upload failed error="upload failed" count=124152026/10/10 19:42:44 INFO Uploading batch count=424162026/10/10 19:42:44 ERROR Upload failed error="upload failed" count=424172026/10/10 19:42:44 INFO Upload queue status pending=224182026/10/10 19:42:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath168008349/002/bbb24192026/10/10 19:42:44 INFO Uploading batch count=22420--- PASS: TestQueueEnqueueAndFetch (0.01s)24212026/10/10 19:42:44 INFO Uploading batch count=124222026/10/10 19:42:44 ERROR Upload failed error="upload failed" count=224232026/10/10 19:42:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1544167040/002/a24242026/10/10 19:42:44 INFO Upload queue status pending=224252026/10/10 19:42:44 INFO Uploading batch count=12426--- PASS: TestQueueRemove (0.01s)24272026/10/10 19:42:44 INFO Uploading batch count=124282026/10/10 19:42:44 INFO Uploading batch count=224292026/10/10 19:42:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1544167040/002/b2430--- PASS: TestQueueRetryMovesToBack (0.01s)2431--- PASS: TestQueueFetchBatchLimit (0.01s)2432--- PASS: TestQueueDeduplication (0.01s)24332026/10/10 19:42:44 INFO Uploading batch count=124342026/10/10 19:42:44 INFO Uploading batch count=124352026/10/10 19:42:44 ERROR Upload failed error="upload failed" count=124362026/10/10 19:42:44 INFO Uploading batch count=224372026/10/10 19:42:44 ERROR Upload failed error="upload failed" count=224382026/10/10 19:42:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1544167040/002/c2439--- PASS: TestQueueFetchRemoveLifecycle (0.02s)24402026/10/10 19:42:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1544167040/002/d24412026/10/10 19:42:44 INFO Uploading batch count=124422026/10/10 19:42:44 ERROR Upload failed error="upload failed" count=124432026/10/10 19:42:44 INFO Uploading batch count=124442026/10/10 19:42:44 ERROR Upload failed error="upload failed" count=124452026/10/10 19:42:44 INFO Uploading batch count=224462026/10/10 19:42:44 ERROR Upload failed error="upload failed" count=224472026/10/10 19:42:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1544167040/002/e24482026/10/10 19:42:44 ERROR Drain finished with paths left in queue remaining=12449--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)24502026/10/10 19:42:44 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1544167040/002/f24512026/10/10 19:42:44 ERROR Drain finished with paths left in queue remaining=102452--- PASS: TestDrainIsolatesPoisonPath (0.02s)2453--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2454--- PASS: TestWorkerPrunesClosureDeps (0.03s)2455--- PASS: TestWorkerSkipsGCdPaths (0.03s)2456--- PASS: TestWorkerUploadsAndRemoves (0.04s)2457--- PASS: TestQueueRemoveLargeClosure (0.11s)2458--- PASS: TestQueueConcurrentWriters (0.13s)24592026/10/10 19:42:44 ERROR Upload failed error="context deadline exceeded" count=224602026/10/10 19:42:44 ERROR Drain finished with paths left in queue remaining=42461--- PASS: TestDrainTimeout (0.21s)24622026/10/10 19:42:45 INFO Uploading batch count=124632026/10/10 19:42:45 INFO Uploading batch count=124642026/10/10 19:42:45 INFO Uploading batch count=124652026/10/10 19:42:45 ERROR Upload failed error="upload failed" count=124662026/10/10 19:42:45 INFO Uploading batch count=124672026/10/10 19:42:45 ERROR Upload failed error="upload failed" count=124682026/10/10 19:42:45 INFO Uploading batch count=124692026/10/10 19:42:45 ERROR Upload failed error="upload failed" count=124702026/10/10 19:42:45 INFO Uploading batch count=124712026/10/10 19:42:45 ERROR Upload failed error="upload failed" count=124722026/10/10 19:42:45 ERROR Drain finished with paths left in queue remaining=12473--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2474PASS2475Running signing tests...2476=== RUN TestExternalSigner2477=== PAUSE TestExternalSigner2478=== RUN TestExternalSignerWrongPublicKey2479=== PAUSE TestExternalSignerWrongPublicKey2480=== RUN TestExternalSignerErrors2481=== PAUSE TestExternalSignerErrors2482=== RUN TestExternalSignerRestartsAfterCrash2483=== PAUSE TestExternalSignerRestartsAfterCrash2484=== RUN TestExternalSignerProgramErrorKeepsProcess2485=== PAUSE TestExternalSignerProgramErrorKeepsProcess2486=== RUN TestExternalSignerClose2487=== PAUSE TestExternalSignerClose2488=== RUN TestExternalSignerRejectsInvalidPublicKey2489=== PAUSE TestExternalSignerRejectsInvalidPublicKey2490=== RUN TestExternalSignerCancellation2491=== PAUSE TestExternalSignerCancellation2492=== RUN TestGenerateFingerprint2493=== PAUSE TestGenerateFingerprint2494=== RUN TestParseSigningKey2495=== PAUSE TestParseSigningKey2496=== RUN TestSign2497=== PAUSE TestSign2498=== RUN TestSignBatch2499=== PAUSE TestSignBatch2500=== RUN TestNilKeyPublicKey2501=== PAUSE TestNilKeyPublicKey2502=== RUN TestSignErrors2503=== PAUSE TestSignErrors2504=== CONT TestExternalSigner2505=== CONT TestExternalSignerCancellation2506=== CONT TestGenerateFingerprint2507=== CONT TestExternalSignerProgramErrorKeepsProcess2508=== RUN TestGenerateFingerprint/basic_with_references2509=== CONT TestExternalSignerRestartsAfterCrash2510=== PAUSE TestGenerateFingerprint/basic_with_references2511=== CONT TestExternalSignerRejectsInvalidPublicKey2512=== RUN TestExternalSignerRejectsInvalidPublicKey/#002513=== CONT TestExternalSignerWrongPublicKey2514=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002515=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2516=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2517=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2518=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2519=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2520=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2521=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2522=== CONT TestSignBatch2523=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2524=== CONT TestExternalSignerRejectsInvalidPublicKey/#002525=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2526=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2527=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2528=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2529--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2530 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2531 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2532 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2533 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2534 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2535=== CONT TestSignErrors2536=== CONT TestNilKeyPublicKey2537--- PASS: TestNilKeyPublicKey (0.00s)2538=== CONT TestParseSigningKey2539=== RUN TestParseSigningKey/valid_32-byte_key2540=== PAUSE TestParseSigningKey/valid_32-byte_key2541=== CONT TestSign2542=== CONT TestExternalSignerClose2543=== CONT TestExternalSignerErrors2544=== RUN TestExternalSignerErrors/unrequested_key2545=== PAUSE TestExternalSignerErrors/unrequested_key2546=== RUN TestExternalSignerErrors/invalid_signature_base642547=== PAUSE TestExternalSignerErrors/invalid_signature_base642548=== RUN TestExternalSignerErrors/wrong_signature_length2549=== PAUSE TestExternalSignerErrors/wrong_signature_length2550=== RUN TestExternalSignerErrors/null2551=== RUN TestGenerateFingerprint/no_references2552=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2553=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2554=== PAUSE TestExternalSignerErrors/null2555=== RUN TestParseSigningKey/no_colon2556=== RUN TestExternalSignerErrors/wrong_id2557=== PAUSE TestExternalSignerErrors/wrong_id2558=== PAUSE TestParseSigningKey/no_colon2559=== RUN TestExternalSignerErrors/missing_signatures2560=== PAUSE TestExternalSignerErrors/missing_signatures2561=== PAUSE TestGenerateFingerprint/no_references2562=== RUN TestParseSigningKey/empty_name2563=== PAUSE TestParseSigningKey/empty_name2564=== RUN TestParseSigningKey/invalid_base642565=== PAUSE TestParseSigningKey/invalid_base642566=== RUN TestParseSigningKey/wrong_length2567=== RUN TestExternalSignerErrors/wrong_signatures_shape2568=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2569=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2570=== PAUSE TestParseSigningKey/wrong_length2571=== RUN TestExternalSignerErrors/missing_signature_name2572=== PAUSE TestExternalSignerErrors/missing_signature_name2573=== RUN TestExternalSignerErrors/null_signatures2574=== PAUSE TestExternalSignerErrors/null_signatures2575=== RUN TestExternalSignerErrors/wrong_signature_name2576=== PAUSE TestExternalSignerErrors/wrong_signature_name2577=== RUN TestExternalSignerErrors/program_error2578=== PAUSE TestExternalSignerErrors/program_error2579=== RUN TestExternalSignerErrors/exit_at_startup2580=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2581=== CONT TestParseSigningKey/valid_32-byte_key2582=== CONT TestParseSigningKey/wrong_length2583=== CONT TestParseSigningKey/invalid_base642584=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2585=== CONT TestParseSigningKey/empty_name2586=== CONT TestParseSigningKey/no_colon2587=== PAUSE TestExternalSignerErrors/exit_at_startup2588=== RUN TestExternalSignerErrors/exit_on_request2589=== PAUSE TestExternalSignerErrors/exit_on_request2590=== RUN TestExternalSignerErrors/invalid_JSON2591=== PAUSE TestExternalSignerErrors/invalid_JSON2592=== RUN TestExternalSignerErrors/wrong_shape2593=== PAUSE TestExternalSignerErrors/wrong_shape2594=== RUN TestExternalSignerErrors/too_few_signatures2595=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2596=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2597=== PAUSE TestExternalSignerErrors/too_few_signatures2598=== CONT TestExternalSignerErrors/unrequested_key2599=== CONT TestExternalSignerErrors/too_few_signatures2600=== CONT TestExternalSignerErrors/missing_signature_name2601=== CONT TestExternalSignerErrors/wrong_shape2602=== CONT TestExternalSignerErrors/exit_on_request2603=== RUN TestGenerateFingerprint/invalid_nar_hash_length2604=== CONT TestExternalSignerErrors/invalid_JSON2605=== CONT TestExternalSignerErrors/wrong_signatures_shape2606=== CONT TestExternalSignerErrors/exit_at_startup2607=== CONT TestExternalSignerErrors/program_error2608=== CONT TestExternalSignerErrors/wrong_signature_name2609=== CONT TestExternalSignerErrors/null_signatures2610=== CONT TestExternalSignerErrors/null2611=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2612=== CONT TestExternalSignerErrors/missing_signatures2613--- PASS: TestParseSigningKey (0.00s)2614 --- PASS: TestParseSigningKey/wrong_length (0.00s)2615 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2616 --- PASS: TestParseSigningKey/empty_name (0.00s)2617 --- PASS: TestParseSigningKey/no_colon (0.00s)2618 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2619 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2620=== CONT TestExternalSignerErrors/wrong_id2621=== RUN TestSignErrors/nil_key2622=== PAUSE TestSignErrors/nil_key2623=== RUN TestSignErrors/nil_narinfo2624--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2625=== PAUSE TestSignErrors/nil_narinfo2626=== RUN TestGenerateFingerprint/invalid_store_path_prefix2627=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2628--- PASS: TestSignBatch (0.01s)2629=== CONT TestExternalSignerErrors/invalid_signature_base642630--- PASS: TestSign (0.00s)2631--- PASS: TestExternalSignerWrongPublicKey (0.01s)2632=== RUN TestGenerateFingerprint/invalid_reference_prefix2633=== RUN TestSignErrors/invalid_narinfo2634=== PAUSE TestSignErrors/invalid_narinfo2635=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2636=== RUN TestSignErrors/canceled2637=== PAUSE TestSignErrors/canceled2638=== CONT TestGenerateFingerprint/basic_with_references2639=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2640=== CONT TestGenerateFingerprint/no_references2641=== CONT TestSignErrors/nil_key2642=== CONT TestSignErrors/canceled2643=== CONT TestSignErrors/invalid_narinfo2644=== CONT TestSignErrors/nil_narinfo2645=== CONT TestGenerateFingerprint/invalid_reference_prefix2646=== CONT TestGenerateFingerprint/invalid_store_path_prefix2647=== CONT TestGenerateFingerprint/invalid_nar_hash_length2648=== CONT TestExternalSignerErrors/wrong_signature_length2649=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2650--- PASS: TestSignErrors (0.01s)2651 --- PASS: TestSignErrors/nil_key (0.00s)2652 --- PASS: TestSignErrors/canceled (0.00s)2653 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2654 --- PASS: TestSignErrors/nil_narinfo (0.00s)2655--- PASS: TestGenerateFingerprint (0.01s)2656 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2657 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2658 --- PASS: TestGenerateFingerprint/no_references (0.00s)2659 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2660 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2661 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2662 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2663--- PASS: TestExternalSignerClose (0.01s)2664--- PASS: TestExternalSigner (0.01s)2665--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2666--- PASS: TestExternalSignerErrors (0.00s)2667 --- PASS: TestExternalSignerErrors/missing_signature_name (0.00s)2668 --- PASS: TestExternalSignerErrors/unrequested_key (0.00s)2669 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2670 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2671 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2672 --- PASS: TestExternalSignerErrors/exit_at_startup (0.00s)2673 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2674 --- PASS: TestExternalSignerErrors/wrong_id (0.00s)2675 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2676 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2677 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2678 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.00s)2679 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)2680 --- PASS: TestExternalSignerErrors/null (0.01s)2681 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2682 --- PASS: TestExternalSignerErrors/program_error (0.01s)2683--- PASS: TestExternalSignerCancellation (0.02s)2684PASS2685Running OpenBao signer tests...2686=== RUN TestSign2687=== PAUSE TestSign2688=== RUN TestSignErrors2689=== PAUSE TestSignErrors2690=== RUN TestServe2691=== PAUSE TestServe2692=== RUN TestServeRejectsGarbage2693=== PAUSE TestServeRejectsGarbage2694=== CONT TestSign2695=== CONT TestServeRejectsGarbage2696=== CONT TestServe2697=== CONT TestSignErrors2698--- PASS: TestServeRejectsGarbage (0.00s)2699=== RUN TestSignErrors/http_error2700=== PAUSE TestSignErrors/http_error2701=== RUN TestSignErrors/invalid_json2702=== PAUSE TestSignErrors/invalid_json2703=== RUN TestSignErrors/no_prefix2704=== PAUSE TestSignErrors/no_prefix2705=== RUN TestSignErrors/invalid_base642706=== PAUSE TestSignErrors/invalid_base642707=== CONT TestSignErrors/http_error2708=== CONT TestSignErrors/no_prefix2709=== CONT TestSignErrors/invalid_json2710--- PASS: TestServe (0.00s)2711=== CONT TestSignErrors/invalid_base642712--- PASS: TestSign (0.01s)2713--- PASS: TestSignErrors (0.00s)2714 --- PASS: TestSignErrors/invalid_json (0.00s)2715 --- PASS: TestSignErrors/invalid_base64 (0.00s)2716 --- PASS: TestSignErrors/no_prefix (0.01s)2717 --- PASS: TestSignErrors/http_error (0.01s)2718PASS