niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #474
· raw
1tribuchet: building on jamie2Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_ReturnsAfterDroppedBody20=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestDumpPathCaseHackMatchesNix24--- PASS: TestDumpPathCaseHackMatchesNix (0.04s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== 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 TestRegisterUploadedObject_OutlivesPush56=== PAUSE TestRegisterUploadedObject_OutlivesPush57=== RUN TestResolveStorePath58=== PAUSE TestResolveStorePath59=== RUN TestDoWithRetry_BodyReplayedViaGetBody60=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody61=== RUN TestRetryTimeoutOutlastsMaxRetries62=== PAUSE TestRetryTimeoutOutlastsMaxRetries63=== RUN TestDoWithRetry_FinalResponseBodyReadable64=== PAUSE TestDoWithRetry_FinalResponseBodyReadable65=== RUN TestShellSplit66=== PAUSE TestShellSplit67=== RUN TestShellSplitErrors68=== PAUSE TestShellSplitErrors69=== RUN TestStreamPushReportsEveryPath70=== PAUSE TestStreamPushReportsEveryPath71=== RUN TestStreamPushBatchesUnderLoad72=== PAUSE TestStreamPushBatchesUnderLoad73=== RUN TestStreamPushIsolatesFailures74=== PAUSE TestStreamPushIsolatesFailures75=== RUN TestStreamPushGivesUpOnDeadServer76=== PAUSE TestStreamPushGivesUpOnDeadServer77=== RUN TestStreamPushRequestLine78=== PAUSE TestStreamPushRequestLine79=== RUN TestStreamPushReportsSignatures80=== PAUSE TestStreamPushReportsSignatures81=== RUN TestStreamPushReportsSkippedPaths82=== PAUSE TestStreamPushReportsSkippedPaths83=== RUN TestClientSignaturesByStorePath84=== PAUSE TestClientSignaturesByStorePath85=== RUN TestStreamPushStopsWhenCanceled86=== PAUSE TestStreamPushStopsWhenCanceled87=== RUN TestSetClientTLS88=== PAUSE TestSetClientTLS89=== RUN TestSetClientTLSDoesNotMutateDefaultTransport90=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport91=== RUN TestSetClientTLSErrors92=== PAUSE TestSetClientTLSErrors93=== RUN TestStaticToken94=== PAUSE TestStaticToken95=== RUN TestFileTokenReadsAndCaches96=== PAUSE TestFileTokenReadsAndCaches97=== RUN TestFileTokenMissing98=== PAUSE TestFileTokenMissing99=== RUN TestFileTokenEmpty100=== PAUSE TestFileTokenEmpty101=== RUN TestScriptTokenNoExpiryRerunsEveryCall102=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall103=== RUN TestScriptTokenCachesUntilRefresh104=== PAUSE TestScriptTokenCachesUntilRefresh105=== RUN TestScriptTokenEmptyToken106=== PAUSE TestScriptTokenEmptyToken107=== RUN TestScriptTokenBadJSON108=== PAUSE TestScriptTokenBadJSON109=== RUN TestScriptTokenScriptFails110=== PAUSE TestScriptTokenScriptFails111=== RUN TestScriptTokenEmptyCommand112=== PAUSE TestScriptTokenEmptyCommand113=== CONT TestDoServerRequestAttachesToken114=== CONT TestRetryTimeoutOutlastsMaxRetries115=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess116=== CONT TestEncodeNixBase32WithRealHash117--- PASS: TestEncodeNixBase32WithRealHash (0.00s)118=== CONT TestStaticToken119--- PASS: TestStaticToken (0.00s)120=== CONT TestPathInfoCACompatibility121=== CONT TestSetClientTLSErrors122=== CONT TestParsePathInfoJSONMultiplePaths123=== CONT TestParsePathInfoJSON124=== RUN TestParsePathInfoJSON/Nix_format125=== PAUSE TestParsePathInfoJSON/Nix_format126=== RUN TestParsePathInfoJSON/Lix_format127=== PAUSE TestParsePathInfoJSON/Lix_format128=== RUN TestParsePathInfoJSON/empty_input129=== PAUSE TestParsePathInfoJSON/empty_input130=== RUN TestParsePathInfoJSON/whitespace_only131=== PAUSE TestParsePathInfoJSON/whitespace_only132=== RUN TestParsePathInfoJSON/invalid_JSON133=== PAUSE TestParsePathInfoJSON/invalid_JSON134=== CONT TestSetClientTLSDoesNotMutateDefaultTransport135=== CONT TestPathInfoHashCompatibility136=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)137=== CONT TestConvertHashToNix32138=== CONT TestRateLimiterFeedback139=== CONT TestSetClientTLS140=== CONT TestDoWithRetry_BodyReplayedViaGetBody141=== CONT TestResolveStorePath142=== CONT TestScriptTokenEmptyCommand143=== RUN TestRateLimiterFeedback/429_enables_limiter144=== CONT TestScriptTokenScriptFails1452026/11/09 12:14:29 WARN Rate limiter enabled after throttle name=server-test rate=5146=== CONT TestRegisterUploadedObject_OutlivesPush147=== CONT TestScriptTokenBadJSON148--- PASS: TestScriptTokenEmptyCommand (0.00s)149=== CONT TestUploadMultipart_PartsInParallel150=== CONT TestScriptTokenEmptyToken151=== CONT TestScriptTokenCachesUntilRefresh152=== CONT TestScriptTokenNoExpiryRerunsEveryCall1532026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:394551542026/11/09 12:14:29 WARN Rate limiter enabled after throttle name=server-test rate=51552026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:38395156=== CONT TestFileTokenEmpty157=== CONT TestFileTokenMissing158=== CONT TestFileTokenReadsAndCaches159=== RUN TestPathInfoCACompatibility/null_ca_field1602026/11/09 12:14:29 WARN Rate limiter backed off name=server-test rate=5161=== PAUSE TestPathInfoCACompatibility/null_ca_field162=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths163=== RUN TestConvertHashToNix32/SRI_format_to_Nix321642026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:38395165=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer166=== PAUSE TestRateLimiterFeedback/429_enables_limiter167--- PASS: TestScriptTokenScriptFails (0.00s)168=== CONT TestEncodeNixBase32169=== CONT TestDumpPathWriterError170=== RUN TestSetClientTLSErrors/missing_cert_file171=== RUN TestSetClientTLS/rejects_connection_without_client_cert172=== CONT TestDumpPathSingleFile173=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)174=== CONT TestDumpPathMatchesNix175=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon176=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon177=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI178=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI179=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512180=== CONT TestUploadMultipart_ReturnsAfterDroppedBody181=== CONT TestPartSizeForNAR182=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512183=== RUN TestPartSizeForNAR/zero_stays_at_minimum184=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum1852026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:39455186=== CONT TestCaseHackSuffix187=== RUN TestPathInfoCACompatibility/old_string_format_-_text188=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text189=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32190=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths191--- PASS: TestResolveStorePath (0.00s)192=== RUN TestRateLimiterFeedback/503_enables_limiter193=== PAUSE TestSetClientTLSErrors/missing_cert_file194=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert195=== RUN TestEncodeNixBase32/test_string_hash196=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun197=== CONT TestFilterOversizedClosures198=== RUN TestFilterOversizedClosures/no_limit_keeps_everything199=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything200=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped201=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped202=== RUN TestFilterOversizedClosures/all_closures_skipped203=== PAUSE TestFilterOversizedClosures/all_closures_skipped204=== RUN TestPartSizeForNAR/small_stays_at_minimum205=== PAUSE TestPartSizeForNAR/small_stays_at_minimum206=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum207=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths208=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths209=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive210=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive211=== CONT TestStreamPushReportsSignatures212=== RUN TestPathInfoCACompatibility/new_structured_format_-_text213=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text214=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method215=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method216=== CONT TestStreamPushRequestLine217=== CONT TestStreamPushGivesUpOnDeadServer218=== PAUSE TestRateLimiterFeedback/503_enables_limiter219=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter220=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter221=== CONT TestStreamPushStopsWhenCanceled2222026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:394552232026/11/09 12:14:29 ERROR Upload failed error="connection refused" count=20224=== RUN TestSetClientTLSErrors/missing_key_file2252026/11/09 12:14:29 ERROR Server seems unavailable, giving up on batch untried=17226=== PAUSE TestSetClientTLSErrors/missing_key_file227=== CONT TestClientSignaturesByStorePath228=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA229=== PAUSE TestEncodeNixBase32/test_string_hash230=== CONT TestStreamPushBatchesUnderLoad2312026/11/09 12:14:29 ERROR Upload failed error=boom count=1232=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false233=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false2342026/11/09 12:14:29 ERROR Upload failed error=boom count=1235=== RUN TestEncodeNixBase32/empty_input2362026/11/09 12:14:29 INFO Garbage collection started237=== CONT TestShellSplitErrors238=== CONT TestRegisterUploadedObjectReusesConnections239=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum240=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts241=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts242=== RUN TestPartSizeForNAR/1_TiB243=== PAUSE TestPartSizeForNAR/1_TiB244=== RUN TestConvertHashToNix32/already_Nix32_format245--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)246=== CONT TestStreamPushReportsEveryPath247=== RUN TestPartSizeForNAR/5_TiB_S3_max_object248=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object249=== RUN TestPartSizeForNAR/capped_at_5_GiB250=== PAUSE TestPartSizeForNAR/capped_at_5_GiB251=== PAUSE TestConvertHashToNix32/already_Nix32_format252=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter253=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter254=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry2552026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:39455256=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica257--- PASS: TestDoServerRequestAttachesToken (0.09s)258=== CONT TestStreamPushIsolatesFailures259--- PASS: TestRegisterUploadedObject_OutlivesPush (0.08s)260--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.08s)261=== CONT TestGetStorePathHash262=== RUN TestGetStorePathHash/valid_store_path263=== PAUSE TestGetStorePathHash/valid_store_path264=== CONT TestStreamPushReportsSkippedPaths265=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA266=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true2672026/11/09 12:14:29 ERROR Upload failed error="bad path" count=3268=== CONT TestShellSplit269=== PAUSE TestEncodeNixBase32/empty_input270=== RUN TestConvertHashToNix32/invalid_format271=== CONT TestDoWithRetry_FinalResponseBodyReadable272=== CONT TestParsePathInfoJSON/Nix_format2732026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:39455274=== CONT TestParsePathInfoJSON/empty_input275=== CONT TestParsePathInfoJSON/Lix_format276--- PASS: TestScriptTokenEmptyToken (0.08s)277--- PASS: TestScriptTokenBadJSON (0.08s)278--- PASS: TestFileTokenMissing (0.00s)279--- PASS: TestFileTokenEmpty (0.00s)280=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512281=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI2822026/11/09 12:14:29 WARN Rate limiter enabled after throttle name=server-test rate=5283=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon284=== CONT TestParsePathInfoJSON/invalid_JSON2852026/11/09 12:14:29 INFO Garbage collection started286=== RUN TestSetClientTLSErrors/missing_ca_file2872026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:42999288=== PAUSE TestSetClientTLSErrors/missing_ca_file289=== RUN TestSetClientTLSErrors/invalid_ca_file290=== PAUSE TestSetClientTLSErrors/invalid_ca_file291=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true292=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2932026/11/09 12:14:29 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=2000294=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths295=== RUN TestSetClientTLS/preserves_debug_logging_transport296=== CONT TestPathInfoCACompatibility/null_ca_field2972026/11/09 12:14:29 WARN Rate limiter backed off name=server-test rate=5298=== CONT TestPathInfoCACompatibility/new_structured_format_-_text299=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive300=== CONT TestPathInfoCACompatibility/old_string_format_-_text301=== CONT TestPartSizeForNAR/capped_at_5_GiB302=== CONT TestPartSizeForNAR/zero_stays_at_minimum303=== CONT TestPartSizeForNAR/1_TiB304=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts305=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum306=== CONT TestPartSizeForNAR/small_stays_at_minimum307=== CONT TestRateLimiterFeedback/429_enables_limiter308=== PAUSE TestSetClientTLS/preserves_debug_logging_transport309=== PAUSE TestConvertHashToNix32/invalid_format3102026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:39455311=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter312=== CONT TestPartSizeForNAR/5_TiB_S3_max_object313=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3142026/11/09 12:14:29 WARN Rate limiter enabled after throttle name=s3-test rate=5315=== CONT TestParsePathInfoJSON/whitespace_only3162026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:34861317=== CONT TestEncodeNixBase32/test_string_hash318=== CONT TestEncodeNixBase32/empty_input319=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)3202026/11/09 12:14:29 WARN Rate limiter enabled after throttle name=server-test rate=5321=== CONT TestRateLimiterFeedback/503_enables_limiter3222026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:35003323=== CONT TestSetClientTLSErrors/missing_key_file3242026/11/09 12:14:29 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=0325--- PASS: TestFileTokenReadsAndCaches (0.00s)3262026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:39455327=== CONT TestFilterOversizedClosures/no_limit_keeps_everything3282026/11/09 12:14:29 WARN Rate limiter backed off name=server-test rate=5329=== CONT TestFilterOversizedClosures/all_closures_skipped3302026/11/09 12:14:29 WARN Rate limiter enabled after throttle name=server-test rate=5331=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths3322026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:40205333=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method3342026/11/09 12:14:29 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=50335=== RUN TestGetStorePathHash/basename_without_hyphen_should_error3362026/11/09 12:14:29 WARN Rate limiter backed off name=server-test rate=5337=== CONT TestSetClientTLSErrors/missing_cert_file338=== CONT TestSetClientTLSErrors/invalid_ca_file3392026/11/09 12:14:29 WARN Garbage collection finished on another replica. Its statistics are not available here340=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false3412026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:39455342=== CONT TestSetClientTLSErrors/missing_ca_file343--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.00s)344=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true345=== CONT TestSetClientTLS/rejects_connection_without_client_cert346=== CONT TestConvertHashToNix32/SRI_format_to_Nix32347=== CONT TestSetClientTLS/preserves_debug_logging_transport348=== CONT TestConvertHashToNix32/already_Nix32_format349=== CONT TestConvertHashToNix32/invalid_format3502026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:39455351=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error352=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA353--- PASS: TestStreamPushStopsWhenCanceled (0.00s)354--- PASS: TestClientSignaturesByStorePath (0.00s)355--- PASS: TestStreamPushReportsSignatures (0.00s)356--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)357--- PASS: TestShellSplitErrors (0.00s)358--- PASS: TestStreamPushReportsEveryPath (0.00s)359--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)360--- PASS: TestStreamPushReportsSkippedPaths (0.00s)361--- PASS: TestStreamPushIsolatesFailures (0.00s)362--- PASS: TestShellSplit (0.00s)363--- PASS: TestScriptTokenCachesUntilRefresh (0.08s)364--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.00s)365--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.00s)366--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.00s)367--- PASS: TestConvertHashToNix32 (0.09s)368 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)369 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)370 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)371--- PASS: TestSetClientTLSErrors (0.09s)372 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)373 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)374 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)375 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)376--- PASS: TestStreamPushBatchesUnderLoad (0.00s)377 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)378 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.01s)379=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error380=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error381=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error382--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.01s)383--- PASS: TestPartSizeForNAR (0.01s)384 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)385 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)386 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)387 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)388 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)389 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)390 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)3912026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:39455392--- PASS: TestParsePathInfoJSON (0.01s)393 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)394 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)395 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)396 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)397 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)398--- PASS: TestEncodeNixBase32 (0.01s)399 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)400 --- PASS: TestEncodeNixBase32/empty_input (0.00s)401=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error402=== CONT TestGetStorePathHash/valid_store_path403=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error404--- PASS: TestPathInfoHashCompatibility (0.09s)405 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)406 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)407 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)408 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)409=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error410=== CONT TestGetStorePathHash/basename_without_hyphen_should_error411--- PASS: TestParsePathInfoJSONMultiplePaths (0.10s)412 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)413 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)4142026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:39455415--- PASS: TestPathInfoCACompatibility (0.10s)416 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)417 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)418 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)419 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)420 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)421--- PASS: TestFilterOversizedClosures (0.01s)422 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)423 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)424 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)425--- PASS: TestRateLimiterFeedback (0.09s)426 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)427 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)428 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)429 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)430--- PASS: TestGetStorePathHash (0.02s)431 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)432 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)433 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)434 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)4352026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:394554362026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:394554372026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:394554382026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:39455439--- PASS: TestStreamPushRequestLine (0.03s)4402026/11/09 12:14:29 http: TLS handshake error from 127.0.0.1:33832: remote error: tls: bad certificate4412026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:39455442--- PASS: TestSetClientTLS (0.09s)443 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)444 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.02s)445 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.02s)4462026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:394554472026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:394554482026/11/09 12:14:29 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:39455449--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.13s)450--- PASS: TestDumpPathSingleFile (0.04s)451--- PASS: TestCaseHackSuffix (0.04s)452--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)453--- PASS: TestDumpPathWriterError (0.05s)4542026/11/09 12:14:29 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:41349/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:41349/api/uploads/complete4552026/11/09 12:14:29 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4562026/11/09 12:14:29 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:41349/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:41349/api/uploads/complete4572026/11/09 12:14:29 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4582026/11/09 12:14:29 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:41349/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:41349/api/uploads/complete4592026/11/09 12:14:29 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"460--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.10s)461--- PASS: TestDumpPathMatchesNix (0.10s)462--- PASS: TestUploadMultipart_PartsInParallel (0.71s)463--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)464PASS465Running server tests...466The files belonging to this database system will be owned by user "nixbld".467This user must also own the server process.468469The database cluster will be initialized with locale "C".470The default database encoding has accordingly been set to "SQL_ASCII".471The default text search configuration will be set to "english".472473Data page checksums are enabled.474475creating directory /build/postgres3732161415/data ... ok476creating subdirectories ... ok477selecting dynamic shared memory implementation ... posix478selecting default "max_connections" ... 100479selecting default "shared_buffers" ... 128MB480selecting default time zone ... UTC481creating configuration files ... ok482running bootstrap script ... ok483performing post-bootstrap initialization ... ok484syncing data to disk ... ok485486initdb: warning: enabling "trust" authentication for local connections487initdb: 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.488489Success. You can now start the database server using:490491 pg_ctl -D /build/postgres3732161415/data -l logfile start492493/build/postgres3732161415:5432 - no response4942026-11-09 12:14:31.625 UTC [130] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4952026-11-09 12:14:31.625 UTC [130] LOG: listening on Unix socket "/build/postgres3732161415/.s.PGSQL.5432"4962026-11-09 12:14:31.629 UTC [137] LOG: database system was shut down at 2026-11-09 12:14:31 UTC4972026-11-09 12:14:31.634 UTC [130] LOG: database system is ready to accept connections498/build/postgres3732161415:5432 - accepting connections499=== RUN TestAbortSucceeded500=== PAUSE TestAbortSucceeded501=== RUN TestService_AuthMiddleware502=== PAUSE TestService_AuthMiddleware503=== RUN TestService_AuthMiddleware_MTLSProxyHeader504=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader505=== RUN TestService_AuthMiddleware_MTLSBoundSubjects506=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects507=== RUN TestService_ReadAuthMiddleware508=== PAUSE TestService_ReadAuthMiddleware509=== RUN TestService_AuthMiddleware_OIDC510=== PAUSE TestService_AuthMiddleware_OIDC511=== RUN TestService_RequireScope_OIDC512=== PAUSE TestService_RequireScope_OIDC513=== RUN TestService_ReadScope_PublicByDefault514=== PAUSE TestService_ReadScope_PublicByDefault515=== RUN TestCacheConfigHandler516=== PAUSE TestCacheConfigHandler517=== RUN TestCacheStatsHandler518=== PAUSE TestCacheStatsHandler519=== RUN TestClientCADerivations520=== PAUSE TestClientCADerivations521=== RUN TestClientErrorHandling522=== PAUSE TestClientErrorHandling523=== RUN TestClientIntegration524=== PAUSE TestClientIntegration525=== RUN TestClientMultipleUploads526=== PAUSE TestClientMultipleUploads527=== RUN TestClientWithDependencies528=== PAUSE TestClientWithDependencies529=== RUN TestClientSharedPathCommittedMidPush530=== PAUSE TestClientSharedPathCommittedMidPush531=== RUN TestPinProtectsFromGC532=== PAUSE TestPinProtectsFromGC533=== RUN TestClientPushesUseOnePush534=== PAUSE TestClientPushesUseOnePush535=== RUN TestClientFallsBackToClosures536=== PAUSE TestClientFallsBackToClosures537=== RUN TestDeleteClosuresRacingPins538=== PAUSE TestDeleteClosuresRacingPins539=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock540=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock541=== RUN TestResolveDBConnectionString542=== PAUSE TestResolveDBConnectionString543=== RUN TestConnectWaitsForAPeerMigration544=== PAUSE TestConnectWaitsForAPeerMigration545=== RUN TestLeadElectsOneAndHandsOver546=== PAUSE TestLeadElectsOneAndHandsOver547=== RUN TestLeadIncumbentWinsAfterRestart5482026/11/09 12:14:32 INFO lead: acquired remote=192.0.2.1:12345492026/11/09 12:14:33 INFO lead: released remote=192.0.2.1:12345502026/11/09 12:14:33 INFO lead: acquired remote=192.0.2.1:12345512026/11/09 12:14:34 INFO lead: released remote=192.0.2.1:1234552--- PASS: TestLeadIncumbentWinsAfterRestart (1.90s)553=== RUN TestLeadIncumbentAnnouncesAtOnce554=== PAUSE TestLeadIncumbentAnnouncesAtOnce555=== RUN TestLeadEndsOnShutdown556=== PAUSE TestLeadEndsOnShutdown557=== RUN TestLeadEndsWhenItsConnectionHangs5582026/11/09 12:14:34 INFO lead: acquired remote=192.0.2.1:12345592026-11-09 12:14:35.770 UTC [576] FATAL: terminating connection due to administrator command5602026/11/09 12:14:35 INFO lead: acquired remote=192.0.2.1:12345612026/11/09 12:14:36 WARN lead: lock connection lost error="timeout: context deadline exceeded"5622026/11/09 12:14:36 INFO lead: released remote=192.0.2.1:12345632026/11/09 12:14:37 INFO lead: released remote=192.0.2.1:1234564--- PASS: TestLeadEndsWhenItsConnectionHangs (2.93s)565=== RUN TestGCAdvisoryLockBlocksConcurrentRun566=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun567=== RUN TestGCBugBareHashReferences568=== PAUSE TestGCBugBareHashReferences569=== RUN TestGCMetrics570=== PAUSE TestGCMetrics571=== RUN TestPushDedupSurvivesConcurrentGC572=== PAUSE TestPushDedupSurvivesConcurrentGC573=== RUN TestDeduplicatedObjectsRecordedAsPending574=== PAUSE TestDeduplicatedObjectsRecordedAsPending575=== RUN TestGCSweepSkipsPendingObjects576=== PAUSE TestGCSweepSkipsPendingObjects577=== RUN TestTombstonedObjectOfferedWithoutWaiting578=== PAUSE TestTombstonedObjectOfferedWithoutWaiting579=== RUN TestGCSweepDeliversEachKeyOnce580=== PAUSE TestGCSweepDeliversEachKeyOnce581=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection582=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection583=== RUN TestForceGCDuringPushOffersSweptObject584=== PAUSE TestForceGCDuringPushOffersSweptObject585=== RUN TestFailedS3DeleteKeepsTombstone586=== PAUSE TestFailedS3DeleteKeepsTombstone587=== RUN TestSweepSkipsRowsLockedByPush588=== PAUSE TestSweepSkipsRowsLockedByPush589=== RUN TestRegisterCompletedObjectNeedsPendingRow590=== PAUSE TestRegisterCompletedObjectNeedsPendingRow591=== RUN TestGetExistingObjectsLocksRows592=== PAUSE TestGetExistingObjectsLocksRows593=== RUN TestSweepRechecksPendingAfterLocking594=== PAUSE TestSweepRechecksPendingAfterLocking595=== RUN TestPushWaitsForSweepHoldingRow596=== PAUSE TestPushWaitsForSweepHoldingRow597=== RUN TestCommitRacingPendingCleanupKeepsObjects598=== PAUSE TestCommitRacingPendingCleanupKeepsObjects599=== RUN TestGCEndsOnShutdown600=== PAUSE TestGCEndsOnShutdown601=== RUN TestGCTaskStore_StartNew602=== PAUSE TestGCTaskStore_StartNew603=== RUN TestGCTaskStore_DeduplicateSameParams604=== PAUSE TestGCTaskStore_DeduplicateSameParams605=== RUN TestGCTaskStore_ConflictDifferentParams606=== PAUSE TestGCTaskStore_ConflictDifferentParams607=== RUN TestGCTaskStore_GetEmpty608=== PAUSE TestGCTaskStore_GetEmpty609=== RUN TestGCTaskStore_GetReturnsLatest610=== PAUSE TestGCTaskStore_GetReturnsLatest611=== RUN TestGCTaskStore_CompletedAllowsNewTask612=== PAUSE TestGCTaskStore_CompletedAllowsNewTask613=== RUN TestGCTaskStore_PhaseUpdates614=== PAUSE TestGCTaskStore_PhaseUpdates615=== RUN TestGCTaskStore_Fail616=== PAUSE TestGCTaskStore_Fail617=== RUN TestGracefulShutdownDrainsInflight618=== PAUSE TestGracefulShutdownDrainsInflight619=== RUN TestService_healthCheckHandler620=== PAUSE TestService_healthCheckHandler621=== RUN TestService_readinessHandler622=== PAUSE TestService_readinessHandler623=== RUN TestGenerateLandingPage624=== PAUSE TestGenerateLandingPage625=== RUN TestEnsureAbortUploadsRule626=== PAUSE TestEnsureAbortUploadsRule627=== RUN TestCacheConfigHandlerMaxNarSize628=== PAUSE TestCacheConfigHandlerMaxNarSize629=== RUN TestCreatePendingClosureRejectsOversizedNAR630=== PAUSE TestCreatePendingClosureRejectsOversizedNAR631=== RUN TestNARDeduplicationMetadataUploadBug632=== PAUSE TestNARDeduplicationMetadataUploadBug633=== RUN TestMetricsInventory634=== PAUSE TestMetricsInventory635=== RUN TestMetricsCommit636=== PAUSE TestMetricsCommit637=== RUN TestService_NativeMTLS638=== PAUSE TestService_NativeMTLS639=== RUN TestServerTLSConfig640=== PAUSE TestServerTLSConfig641=== RUN TestMultipartCleanup642=== PAUSE TestMultipartCleanup643=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded644=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded645=== RUN TestPendingCleanupUsesOneCutoff646=== PAUSE TestPendingCleanupUsesOneCutoff647=== RUN TestObjectStatsTrigger648=== PAUSE TestObjectStatsTrigger649=== RUN TestObjectStatsUpdatedOncePerCommit650=== PAUSE TestObjectStatsUpdatedOncePerCommit651=== RUN TestOrphanedObjectsGC652=== PAUSE TestOrphanedObjectsGC653=== RUN TestOrphanedObjectsGCStressTest654=== PAUSE TestOrphanedObjectsGCStressTest655=== RUN TestCreatePin_ReservedPins656=== PAUSE TestCreatePin_ReservedPins657=== RUN TestPresentReportsOnlyClosureRoots658=== PAUSE TestPresentReportsOnlyClosureRoots659=== RUN TestPresentRefreshesOnlyStaleClosures660=== PAUSE TestPresentRefreshesOnlyStaleClosures661=== RUN TestPresentNotReportedWhileGCDeletesClosure662=== PAUSE TestPresentNotReportedWhileGCDeletesClosure663=== RUN TestParseSingleRange664=== PAUSE TestParseSingleRange665=== RUN TestProxyHeadersOnlyTrustedOnSocket6662026/11/09 12:14:37 INFO Starting HTTP server address=127.0.0.1:408056672026/11/09 12:14:37 INFO Starting HTTP server address=proxy.sock6682026/11/09 12:14:37 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6692026/11/09 12:14:37 INFO Shutdown signal received, draining in-flight requests timeout=10s670--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.13s)671=== RUN TestIsValidCachePath672=== PAUSE TestIsValidCachePath673=== RUN TestReadProxyNarinfo674=== PAUSE TestReadProxyNarinfo675=== RUN TestReadProxyNarinfoAlreadyDecompressed676=== PAUSE TestReadProxyNarinfoAlreadyDecompressed677=== RUN TestReadProxyContentNegotiation678=== PAUSE TestReadProxyContentNegotiation679=== RUN TestReadProxyNarStreaming680=== PAUSE TestReadProxyNarStreaming681=== RUN TestReadProxy404682=== PAUSE TestReadProxy404683=== RUN TestReadProxyInvalidPath684=== PAUSE TestReadProxyInvalidPath685=== RUN TestReadProxyHead686=== PAUSE TestReadProxyHead687=== RUN TestReadProxyOutlastsServerWriteTimeout688=== PAUSE TestReadProxyOutlastsServerWriteTimeout689=== RUN TestReadProxyConditionalGet690=== PAUSE TestReadProxyConditionalGet691=== RUN TestReadProxyRootRedirectsToIndexHTML692=== PAUSE TestReadProxyRootRedirectsToIndexHTML693=== RUN TestReadProxyDisabled694=== PAUSE TestReadProxyDisabled695=== RUN TestReadRedirectNar696=== PAUSE TestReadRedirectNar697=== RUN TestReadRedirectKeepsNarinfoProxied698=== PAUSE TestReadRedirectKeepsNarinfoProxied699=== RUN TestReadProxyRangeRequest700=== PAUSE TestReadProxyRangeRequest701=== RUN TestReadRedirectUsesPublicS3URL702=== PAUSE TestReadRedirectUsesPublicS3URL703=== RUN TestPush_OverlappingRootsStoreOneRowPerKey704=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey705=== RUN TestPush_CompleteCommitsEveryRoot706=== PAUSE TestPush_CompleteCommitsEveryRoot707=== RUN TestPush_RepeatedRootCommitsOnce708=== PAUSE TestPush_RepeatedRootCommitsOnce709=== RUN TestPush_CompleteWaitsForCleanupOfThePush710=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush711=== RUN TestPush_RootsAreLockedInByteOrder712=== PAUSE TestPush_RootsAreLockedInByteOrder713=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit714=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit715=== RUN TestPush_RejectsBadRequests716=== PAUSE TestPush_RejectsBadRequests717=== RUN TestPush_SignsNarinfosOfItsPendingObjects718=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects719=== RUN TestSharedNarBothUploadsComplete720=== PAUSE TestSharedNarBothUploadsComplete721=== RUN TestCompleteMultipartUpload_ErrorButObjectExists722=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists723=== RUN TestCompletedNarNotReofferedAcrossClosures724=== PAUSE TestCompletedNarNotReofferedAcrossClosures725=== RUN TestPresignedUploadRegisteredBeforeCommit726=== PAUSE TestPresignedUploadRegisteredBeforeCommit727=== RUN TestService_Rustfstest728=== PAUSE TestService_Rustfstest729=== RUN TestParseSize730=== PAUSE TestParseSize731=== RUN TestSkippedUploadsHandler732=== PAUSE TestSkippedUploadsHandler733=== RUN TestSystemdListenerNotActivated734--- PASS: TestSystemdListenerNotActivated (0.00s)735=== RUN TestWatchdogBeatsWhenHealthy736--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)737=== RUN TestWatchdogSkipsWhenUnhealthy7382026/11/09 12:14:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7392026/11/09 12:14:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7402026/11/09 12:14:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7412026/11/09 12:14:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7422026/11/09 12:14:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7432026/11/09 12:14:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7442026/11/09 12:14:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7452026/11/09 12:14:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/09 12:14:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/09 12:14:37 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"748--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)749=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle750=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle751=== RUN TestProxyWriteTimeout752=== PAUSE TestProxyWriteTimeout753=== RUN TestPendingClosureWriteTimeout754=== PAUSE TestPendingClosureWriteTimeout755=== RUN TestIsValidUploadKey756=== PAUSE TestIsValidUploadKey757=== RUN TestUploadHandlersRejectInvalidKeys758=== PAUSE TestUploadHandlersRejectInvalidKeys759=== RUN TestUploadHandlersRejectOversizedBody760=== PAUSE TestUploadHandlersRejectOversizedBody761=== RUN TestService_cleanupPendingClosuresHandler762=== PAUSE TestService_cleanupPendingClosuresHandler763=== RUN TestService_createPendingClosureHandler764=== PAUSE TestService_createPendingClosureHandler765=== RUN TestService_verifyS3Integrity766=== PAUSE TestService_verifyS3Integrity767=== RUN TestService_verifyS3ReuploadsStaleNarinfo768=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo769=== RUN TestCompleteMultipartUnregistered770=== PAUSE TestCompleteMultipartUnregistered771=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT772=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT773=== CONT TestAbortSucceeded774--- PASS: TestAbortSucceeded (0.00s)775=== CONT TestReadProxyNarinfo776=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT777=== CONT TestCompleteMultipartUnregistered778=== CONT TestService_verifyS3ReuploadsStaleNarinfo779=== CONT TestService_verifyS3Integrity780=== CONT TestService_createPendingClosureHandler781=== CONT TestService_cleanupPendingClosuresHandler782=== CONT TestUploadHandlersRejectOversizedBody783=== CONT TestUploadHandlersRejectInvalidKeys784=== CONT TestIsValidUploadKey785=== CONT TestPendingClosureWriteTimeout786=== RUN TestPendingClosureWriteTimeout/empty787=== CONT TestProxyWriteTimeout788=== RUN TestProxyWriteTimeout/narinfo789=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle790=== CONT TestSkippedUploadsHandler791=== CONT TestParseSize792=== CONT TestService_Rustfstest793=== CONT TestPresignedUploadRegisteredBeforeCommit794=== CONT TestCompletedNarNotReofferedAcrossClosures795=== CONT TestCompleteMultipartUpload_ErrorButObjectExists796=== CONT TestGetExistingObjectsLocksRows797=== CONT TestSharedNarBothUploadsComplete798=== CONT TestPush_SignsNarinfosOfItsPendingObjects799=== CONT TestIsValidCachePath800=== CONT TestPush_RejectsBadRequests801=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed802=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info803=== PAUSE TestPendingClosureWriteTimeout/empty804=== RUN TestIsValidUploadKey/narinfo805=== PAUSE TestProxyWriteTimeout/narinfo806=== RUN TestProxyWriteTimeout/1_GiB_nar8072026/11/09 12:14:37 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000808=== PAUSE TestProxyWriteTimeout/1_GiB_nar809=== RUN TestProxyWriteTimeout/10_GiB_nar810=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed811=== CONT TestParseSingleRange812=== RUN TestPendingClosureWriteTimeout/400_objects813--- PASS: TestParseSize (0.00s)814=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed815=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed816=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost817=== PAUSE TestIsValidUploadKey/narinfo818=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info819=== RUN TestParseSingleRange/none820=== RUN TestIsValidUploadKey/nar_zst821=== PAUSE TestProxyWriteTimeout/10_GiB_nar822=== RUN TestProxyWriteTimeout/unknown_size823=== PAUSE TestProxyWriteTimeout/unknown_size824=== PAUSE TestPendingClosureWriteTimeout/400_objects825=== RUN TestPendingClosureWriteTimeout/670k_objects826=== RUN TestIsValidCachePath/narinfo827=== PAUSE TestParseSingleRange/none828=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost829=== PAUSE TestIsValidUploadKey/nar_zst830=== RUN TestIsValidUploadKey/nar_xz831=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit832=== PAUSE TestPendingClosureWriteTimeout/670k_objects833=== PAUSE TestIsValidUploadKey/nar_xz834=== PAUSE TestIsValidCachePath/narinfo835=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars836=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars837=== RUN TestIsValidCachePath/nar_zst838=== PAUSE TestIsValidCachePath/nar_zst839=== RUN TestIsValidCachePath/nar_xz840=== PAUSE TestIsValidCachePath/nar_xz841=== RUN TestIsValidCachePath/nar_bz2842=== PAUSE TestIsValidCachePath/nar_bz2843=== RUN TestIsValidCachePath/nar_uncompressed844=== PAUSE TestIsValidCachePath/nar_uncompressed845=== RUN TestIsValidCachePath/ls846=== PAUSE TestIsValidCachePath/ls847=== RUN TestIsValidCachePath/log848=== PAUSE TestIsValidCachePath/log849=== RUN TestIsValidCachePath/realisation850=== PAUSE TestIsValidCachePath/realisation851=== RUN TestIsValidCachePath/nix-cache-info852=== PAUSE TestIsValidCachePath/nix-cache-info853=== RUN TestIsValidCachePath/index.html854=== PAUSE TestIsValidCachePath/index.html855=== RUN TestIsValidCachePath/traversal_parent856=== PAUSE TestIsValidCachePath/traversal_parent857=== RUN TestIsValidCachePath/traversal_in_middle858=== PAUSE TestIsValidCachePath/traversal_in_middle859=== RUN TestIsValidCachePath/invalid_char_e860=== PAUSE TestIsValidCachePath/invalid_char_e861=== RUN TestIsValidCachePath/invalid_char_u862=== PAUSE TestIsValidCachePath/invalid_char_u863=== RUN TestIsValidCachePath/random_path864=== PAUSE TestIsValidCachePath/random_path865=== RUN TestIsValidCachePath/empty866=== PAUSE TestIsValidCachePath/empty867=== RUN TestIsValidCachePath/leading_slash868=== PAUSE TestIsValidCachePath/leading_slash869=== RUN TestIsValidCachePath/wrong_extension870=== PAUSE TestIsValidCachePath/wrong_extension871=== RUN TestIsValidCachePath/short_hash872=== PAUSE TestIsValidCachePath/short_hash873=== RUN TestIsValidUploadKey/nar_plain874=== PAUSE TestIsValidUploadKey/nar_plain875=== RUN TestIsValidUploadKey/listing876=== PAUSE TestIsValidUploadKey/listing877=== RUN TestIsValidUploadKey/build_log878=== PAUSE TestIsValidUploadKey/build_log879=== RUN TestIsValidUploadKey/build_log_home-manager_file880=== PAUSE TestIsValidUploadKey/build_log_home-manager_file881=== RUN TestIsValidUploadKey/build_log_plus_in_name882=== PAUSE TestIsValidUploadKey/build_log_plus_in_name883=== RUN TestIsValidUploadKey/build_log_question_mark884=== CONT TestPresentNotReportedWhileGCDeletesClosure885=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale886=== PAUSE TestIsValidUploadKey/build_log_question_mark887=== RUN TestParseSingleRange/unknown_unit888=== PAUSE TestParseSingleRange/unknown_unit889=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale890=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline891=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline892=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal893=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed894=== RUN TestIsValidUploadKey/build_log_equals895=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal896=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key897=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key898=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key899=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key900=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh901=== CONT TestPush_RootsAreLockedInByteOrder902=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed903=== RUN TestParseSingleRange/multi-range_ignored904=== PAUSE TestIsValidUploadKey/build_log_equals905=== RUN TestIsValidUploadKey/realisation906=== PAUSE TestIsValidUploadKey/realisation907=== RUN TestIsValidUploadKey/realisation_plus_in_output908=== PAUSE TestIsValidUploadKey/realisation_plus_in_output909=== CONT TestPresentRefreshesOnlyStaleClosures910=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh911=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed912=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed913=== PAUSE TestParseSingleRange/multi-range_ignored914=== CONT TestPush_CompleteWaitsForCleanupOfThePush915=== RUN TestParseSingleRange/malformed_no_dash916=== PAUSE TestParseSingleRange/malformed_no_dash917=== CONT TestPresentReportsOnlyClosureRoots918=== RUN TestIsValidUploadKey/nix-cache-info919=== PAUSE TestIsValidUploadKey/nix-cache-info920=== RUN TestIsValidUploadKey/index.html921=== PAUSE TestIsValidUploadKey/index.html922=== RUN TestIsValidUploadKey/narinfo_key,_nar_type923=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type924=== RUN TestIsValidUploadKey/nar_key,_narinfo_type925=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type926=== RUN TestIsValidUploadKey/listing_key,_narinfo_type927=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type928=== RUN TestIsValidUploadKey/traversal929=== PAUSE TestIsValidUploadKey/traversal930=== RUN TestParseSingleRange/malformed_both_empty931--- PASS: TestSkippedUploadsHandler (0.10s)932=== CONT TestPush_RepeatedRootCommitsOnce933=== RUN TestIsValidUploadKey/traversal_nar934=== PAUSE TestIsValidUploadKey/traversal_nar935=== PAUSE TestParseSingleRange/malformed_both_empty936=== RUN TestIsValidUploadKey/absolute937=== PAUSE TestIsValidUploadKey/absolute938=== RUN TestParseSingleRange/malformed_end_before_start939=== PAUSE TestParseSingleRange/malformed_end_before_start940=== RUN TestParseSingleRange/closed941=== PAUSE TestParseSingleRange/closed942=== RUN TestParseSingleRange/open-ended943=== PAUSE TestParseSingleRange/open-ended944=== RUN TestParseSingleRange/end_clamped_to_size945=== PAUSE TestParseSingleRange/end_clamped_to_size946=== RUN TestParseSingleRange/suffix947=== PAUSE TestParseSingleRange/suffix948=== RUN TestParseSingleRange/suffix_exceeds_size949=== PAUSE TestParseSingleRange/suffix_exceeds_size950=== RUN TestParseSingleRange/single_byte951=== PAUSE TestParseSingleRange/single_byte952=== RUN TestParseSingleRange/start_past_EOF953=== PAUSE TestParseSingleRange/start_past_EOF954=== RUN TestParseSingleRange/start_far_past_EOF955=== PAUSE TestParseSingleRange/start_far_past_EOF956=== RUN TestIsValidUploadKey/empty_key957=== PAUSE TestIsValidUploadKey/empty_key958=== RUN TestIsValidUploadKey/unknown_type959=== PAUSE TestIsValidUploadKey/unknown_type960=== CONT TestCreatePin_ReservedPins961=== CONT TestOrphanedObjectsGCStressTest9622026/11/09 12:14:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44847/oidc963=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure964=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure965=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart966=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart967=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts968=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts969=== CONT TestPush_CompleteCommitsEveryRoot970--- PASS: TestService_Rustfstest (0.47s)971=== CONT TestOrphanedObjectsGC9722026/11/09 12:14:38 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>973--- PASS: TestReadProxyNarinfo (0.48s)974=== CONT TestPush_OverlappingRootsStoreOneRowPerKey975--- PASS: TestGetExistingObjectsLocksRows (0.50s)976=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock9772026/11/09 12:14:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9782026/11/09 12:14:38 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst979--- PASS: TestCompleteMultipartUnregistered (0.52s)980=== CONT TestObjectStatsUpdatedOncePerCommit9812026/11/09 12:14:38 INFO Received cleanup request method=DELETE path=/api/pending_closures9822026/11/09 12:14:38 INFO Aborted multipart uploads count=0 kept=09832026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures9842026/11/09 12:14:38 INFO Received cleanup request method=DELETE path=/api/pending_closures9852026/11/09 12:14:38 INFO Aborted multipart uploads count=1 kept=09862026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures9872026/11/09 12:14:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9882026-11-09 12:14:38.093 UTC [657] ERROR: Closure does not exist: id=19892026-11-09 12:14:38.093 UTC [657] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9902026-11-09 12:14:38.093 UTC [657] STATEMENT: -- name: CommitPendingClosure :one991 SELECT commit_pending_closure($1::bigint)::bigint992 993--- PASS: TestService_cleanupPendingClosuresHandler (0.56s)994=== CONT TestReadRedirectUsesPublicS3URL9952026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures9962026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures9972026/11/09 12:14:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9982026/11/09 12:14:38 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LjhiNTdjMTMyLTI1YTgtNDZhZC1hZjNmLTg1NmEzOTA3OWE0ZngxNzk0MjI2NDc4MTE4Mzg3MTQ59992026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures10002026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures10012026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures10022026/11/09 12:14:38 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10032026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures10042026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures10052026/11/09 12:14:38 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LjhiNTdjMTMyLTI1YTgtNDZhZC1hZjNmLTg1NmEzOTA3OWE0ZngxNzk0MjI2NDc4MTE4Mzg3MTQ5 parts=11006--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.63s)1007=== CONT TestRegisterCompletedObjectNeedsPendingRow1008--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.63s)1009=== CONT TestObjectStatsTrigger1010--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.64s)1011=== CONT TestSweepSkipsRowsLockedByPush10122026/11/09 12:14:38 INFO Received push request method=POST path=/api/pushes10132026/11/09 12:14:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10142026/11/09 12:14:38 INFO Signed narinfos id=1 count=110152026/11/09 12:14:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10162026/11/09 12:14:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10172026/11/09 12:14:38 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10182026/11/09 12:14:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10192026/11/09 12:14:38 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10202026/11/09 12:14:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10212026/11/09 12:14:38 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110222026/11/09 12:14:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10232026/11/09 12:14:38 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1024--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.66s)1025=== CONT TestReadProxyRangeRequest10262026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures10272026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures1028--- PASS: TestPresentRefreshesOnlyStaleClosures (0.65s)1029=== CONT TestPendingCleanupUsesOneCutoff10302026/11/09 12:14:38 INFO Received push request method=POST path=/api/pushes10312026/11/09 12:14:38 INFO Received complete push request method=POST path=/api/pushes/1/complete10322026/11/09 12:14:38 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10332026/11/09 12:14:38 WARN Refused reserved pin name=worker-x86_64-linux10342026/11/09 12:14:38 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10352026/11/09 12:14:38 INFO Received create pin request method=POST path=/api/pins/my-app10362026/11/09 12:14:38 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1037--- PASS: TestCreatePin_ReservedPins (0.67s)1038=== CONT TestReadRedirectKeepsNarinfoProxied10392026/11/09 12:14:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10402026/11/09 12:14:38 INFO Completed push id=1 objects=4 duration=10.469725ms10412026/11/09 12:14:38 INFO Received push request method=POST path=/api/pushes1042=== RUN TestPush_RejectsBadRequests/no_roots1043=== PAUSE TestPush_RejectsBadRequests/no_roots1044=== RUN TestPush_RejectsBadRequests/no_objects1045=== PAUSE TestPush_RejectsBadRequests/no_objects1046=== RUN TestPush_RejectsBadRequests/bad_root1047=== PAUSE TestPush_RejectsBadRequests/bad_root1048=== RUN TestPush_RejectsBadRequests/root_not_in_objects1049=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1050=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded10512026/11/09 12:14:38 INFO Received push request method=POST path=/api/pushes10522026/11/09 12:14:38 INFO Received complete push request method=POST path=/api/pushes/1/complete10532026/11/09 12:14:38 INFO Received push request method=POST path=/api/pushes10542026/11/09 12:14:38 INFO Aborted multipart uploads count=0 kept=010552026/11/09 12:14:38 INFO Completed push id=1 objects=4 duration=21.461859ms1056--- PASS: TestPush_RepeatedRootCommitsOnce (0.75s)1057=== CONT TestFailedS3DeleteKeepsTombstone10582026/11/09 12:14:38 WARN Force mode enabled - objects will be deleted immediately without grace period10592026/11/09 12:14:38 INFO Received push request method=POST path=/api/pushes10602026/11/09 12:14:38 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=010612026/11/09 12:14:38 INFO Vacuumed table table=pending_closures10622026/11/09 12:14:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10632026/11/09 12:14:38 INFO Vacuumed table table=pending_objects10642026/11/09 12:14:38 INFO Vacuumed table table=multipart_uploads10652026/11/09 12:14:38 INFO Vacuumed table table=closures10662026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures10672026/11/09 12:14:38 INFO Vacuumed table table=objects10682026/11/09 12:14:38 INFO Received complete push request method=POST path=/api/pushes/2/complete10692026/11/09 12:14:38 INFO Completed push id=2 objects=4 duration=3.468972ms1070--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.80s)1071=== CONT TestReadRedirectNar10722026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures10732026/11/09 12:14:38 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LjgwNjdiZGE0LWRlODctNDk0OC04ZmJlLWUwZTFmNmNlM2M1ZngxNzk0MjI2NDc4MDk5MDc1MjQx parts=1010742026/11/09 12:14:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10752026-11-09 12:14:38.438 UTC [724] ERROR: could not obtain lock on row in relation "closures"10762026-11-09 12:14:38.438 UTC [724] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10772026-11-09 12:14:38.438 UTC [724] ERROR: could not obtain lock on row in relation "closures"10782026-11-09 12:14:38.438 UTC [724] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10792026-11-09 12:14:38.438 UTC [724] ERROR: could not obtain lock on row in relation "closures"10802026-11-09 12:14:38.438 UTC [724] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10812026-11-09 12:14:38.439 UTC [724] ERROR: could not obtain lock on row in relation "closures"10822026-11-09 12:14:38.439 UTC [724] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10832026-11-09 12:14:38.439 UTC [724] ERROR: could not obtain lock on row in relation "closures"10842026-11-09 12:14:38.439 UTC [724] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10852026/11/09 12:14:38 INFO Completed upload id=1 objects=2 duration=6.399023ms10862026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures1087--- PASS: TestPush_RootsAreLockedInByteOrder (0.81s)1088=== CONT TestForceGCDuringPushOffersSweptObject1089=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1090=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1091=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1092=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1093=== CONT TestReadProxyDisabled10942026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures10952026/11/09 12:14:38 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10962026/11/09 12:14:38 WARN Found objects in DB but missing from S3, will re-upload count=11097--- PASS: TestService_verifyS3Integrity (0.92s)1098=== CONT TestMultipartCleanup1099--- PASS: TestPresentReportsOnlyClosureRoots (0.83s)1100=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection11012026/11/09 12:14:38 INFO Received push request method=POST path=/api/pushes11022026/11/09 12:14:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11032026/11/09 12:14:38 INFO Received complete push request method=POST path=/api/pushes/1/complete11042026/11/09 12:14:38 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LmFhNjkwM2FkLWE4MTUtNGE3OS05ZGUyLTg3YWY5YTM4MTJiZHgxNzk0MjI2NDc4MTcyODMzNjYx parts=1011052026/11/09 12:14:38 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11062026/11/09 12:14:38 INFO Completed push id=1 objects=6 duration=12.891575ms1107--- PASS: TestPush_CompleteCommitsEveryRoot (0.78s)1108=== CONT TestReadProxyRootRedirectsToIndexHTML11092026/11/09 12:14:38 INFO Completed upload id=1 objects=2 duration=6.303572ms11102026/11/09 12:14:38 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011112026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures11122026/11/09 12:14:38 INFO Starting cleanup of old closures method=DELETE path=/api/closures11132026/11/09 12:14:38 INFO Aborted multipart uploads count=0 kept=011142026/11/09 12:14:38 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=011152026/11/09 12:14:38 INFO Vacuumed table table=pending_closures11162026/11/09 12:14:38 INFO Vacuumed table table=pending_objects11172026/11/09 12:14:38 INFO Vacuumed table table=multipart_uploads11182026/11/09 12:14:38 INFO Vacuumed table table=closures11192026/11/09 12:14:38 INFO Received push request method=POST path=/api/pushes11202026/11/09 12:14:38 INFO Vacuumed table table=objects11212026/11/09 12:14:38 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001122--- PASS: TestService_createPendingClosureHandler (1.05s)1123=== CONT TestServerTLSConfig1124=== RUN TestServerTLSConfig/no_client_CA1125=== PAUSE TestServerTLSConfig/no_client_CA1126=== RUN TestServerTLSConfig/missing_CA_file1127=== PAUSE TestServerTLSConfig/missing_CA_file1128=== RUN TestServerTLSConfig/not_a_PEM_file1129=== PAUSE TestServerTLSConfig/not_a_PEM_file1130=== CONT TestGCSweepDeliversEachKeyOnce1131--- PASS: TestObjectStatsUpdatedOncePerCommit (0.56s)1132=== CONT TestService_NativeMTLS1133--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.60s)1134=== CONT TestReadProxyConditionalGet11352026/11/09 12:14:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1136--- PASS: TestReadRedirectUsesPublicS3URL (0.56s)1137=== CONT TestMetricsCommit11382026/11/09 12:14:38 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LmIwMjE5OWZhLTljZmEtNDZiYy05MzE3LWNmNzgyNDM0MjJkZXgxNzk0MjI2NDc4MjIxMzU0NzUx parts=1211392026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures1140--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.12s)1141=== CONT TestTombstonedObjectOfferedWithoutWaiting1142--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.50s)1143=== CONT TestReadProxyOutlastsServerWriteTimeout11442026-11-09 12:14:38.697 UTC [714] ERROR: Push does not exist: id=111452026-11-09 12:14:38.697 UTC [714] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11462026-11-09 12:14:38.697 UTC [714] STATEMENT: SELECT commit_push($1)1147--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (1.06s)1148=== CONT TestReadProxyHead1149--- PASS: TestObjectStatsTrigger (0.56s)1150=== CONT TestReadProxyInvalidPath11512026/11/09 12:14:38 INFO Aborted multipart uploads count=0 kept=01152--- PASS: TestReadProxyRangeRequest (0.55s)1153=== CONT TestReadProxy40411542026/11/09 12:14:38 WARN Force mode enabled - objects will be deleted immediately without grace period11552026/11/09 12:14:38 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=011562026/11/09 12:14:38 INFO Vacuumed table table=pending_closures11572026/11/09 12:14:38 INFO Vacuumed table table=pending_objects11582026/11/09 12:14:38 INFO Vacuumed table table=multipart_uploads11592026/11/09 12:14:38 INFO Vacuumed table table=closures11602026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures11612026/11/09 12:14:38 INFO Vacuumed table table=objects11622026/11/09 12:14:38 INFO Aborted multipart uploads count=0 kept=011632026/11/09 12:14:38 WARN Force mode enabled - objects will be deleted immediately without grace period1164--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.75s)1165=== CONT TestGCSweepSkipsPendingObjects11662026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures11672026/11/09 12:14:38 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=011682026/11/09 12:14:38 INFO Received cleanup request method=DELETE path=/api/pending_closures11692026/11/09 12:14:38 INFO Vacuumed table table=pending_closures11702026/11/09 12:14:38 INFO Vacuumed table table=pending_objects11712026/11/09 12:14:38 INFO Vacuumed table table=multipart_uploads11722026/11/09 12:14:38 INFO Vacuumed table table=closures1173--- PASS: TestReadRedirectKeepsNarinfoProxied (0.50s)1174=== CONT TestReadProxyNarStreaming11752026/11/09 12:14:38 INFO Vacuumed table table=objects1176--- PASS: TestSweepSkipsRowsLockedByPush (0.63s)1177=== CONT TestReadProxyContentNegotiation11782026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures1179--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.51s)1180=== CONT TestReadProxyNarinfoAlreadyDecompressed11812026/11/09 12:14:38 INFO Received uploads request method=POST path=/api/pending_closures11822026/11/09 12:14:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1183--- PASS: TestReadRedirectNar (0.44s)1184=== CONT TestDeduplicatedObjectsRecordedAsPending11852026/11/09 12:14:39 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LmIwOWU2YjEyLWIyMmQtNDlkOC05ODE2LWQzY2ExZjhkNDU4OHgxNzk0MjI2NDc4NDI5NjIzNDE3 parts=121186--- PASS: TestReadProxyDisabled (0.61s)1187=== CONT TestPushDedupSurvivesConcurrentGC11882026/11/09 12:14:39 INFO Received uploads request method=POST path=/api/pending_closures11892026/11/09 12:14:39 INFO Aborted multipart uploads count=0 kept=011902026/11/09 12:14:39 WARN Force mode enabled - objects will be deleted immediately without grace period11912026/11/09 12:14:39 INFO Received uploads request method=POST path=/api/pending_closures11922026/11/09 12:14:39 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11932026/11/09 12:14:39 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1194--- PASS: TestFailedS3DeleteKeepsTombstone (0.74s)1195=== CONT TestGCTaskStore_PhaseUpdates1196--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1197=== CONT TestGCMetrics1198--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.61s)1199=== CONT TestNARDeduplicationMetadataUploadBug1200--- PASS: TestReadProxyConditionalGet (0.57s)1201=== CONT TestGCBugBareHashReferences12022026/11/09 12:14:39 INFO Aborted multipart uploads count=0 kept=012032026/11/09 12:14:39 WARN mTLS auth: subject not in bound subjects subject="CN=reader"12042026/11/09 12:14:39 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1205--- PASS: TestService_NativeMTLS (0.60s)12062026/11/09 12:14:39 WARN Force mode enabled - objects will be deleted immediately without grace period1207=== CONT TestCreatePendingClosureRejectsOversizedNAR12082026/11/09 12:14:39 INFO Received uploads request method=POST path=/api/pending_closures1209--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1210=== CONT TestGCAdvisoryLockBlocksConcurrentRun1211=== NAME TestOrphanedObjectsGC1212 orphaned_objects_gc_test.go:287: GC Test Summary:1213 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1214 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1215 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1216 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1217 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1218--- PASS: TestOrphanedObjectsGC (1.21s)1219=== CONT TestCacheConfigHandlerMaxNarSize1220--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1221=== CONT TestLeadEndsOnShutdown12222026/11/09 12:14:39 INFO Received cleanup request method=DELETE path=/api/pending_closures12232026/11/09 12:14:39 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket43/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""12242026/11/09 12:14:39 INFO Aborted multipart uploads count=0 kept=112252026/11/09 12:14:39 INFO Received cleanup request method=DELETE path=/api/pending_closures12262026/11/09 12:14:39 INFO Aborted multipart uploads count=1 kept=012272026/11/09 12:14:39 INFO Received uploads request method=POST path=/api/pending_closures1228--- PASS: TestMultipartCleanup (0.78s)1229=== CONT TestMetricsInventory1230--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.58s)1231=== CONT TestLeadIncumbentAnnouncesAtOnce12322026/11/09 12:14:39 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=012332026/11/09 12:14:39 INFO Received push request method=POST path=/api/pushes12342026/11/09 12:14:39 INFO Vacuumed table table=pending_closures12352026/11/09 12:14:39 INFO Vacuumed table table=pending_objects12362026/11/09 12:14:39 INFO Vacuumed table table=multipart_uploads12372026/11/09 12:14:39 INFO Vacuumed table table=closures12382026/11/09 12:14:39 INFO Vacuumed table table=objects1239--- PASS: TestGCSweepDeliversEachKeyOnce (0.67s)1240=== CONT TestGCTaskStore_CompletedAllowsNewTask1241--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1242=== CONT TestEnsureAbortUploadsRule12432026/11/09 12:14:39 INFO Received complete push request method=POST path=/api/pushes/1/complete12442026/11/09 12:14:39 INFO Completed push id=1 objects=4 duration=11.722984ms12452026/11/09 12:14:39 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete12462026/11/09 12:14:39 INFO Completed upload id=2 objects=2 duration=1.455271ms1247--- PASS: TestMetricsCommit (0.64s)1248=== CONT TestLeadElectsOneAndHandsOver1249--- PASS: TestReadProxyHead (0.60s)1250=== CONT TestGCTaskStore_GetReturnsLatest1251--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1252=== CONT TestConnectWaitsForAPeerMigration1253--- PASS: TestReadProxyInvalidPath (0.58s)1254=== CONT TestResolveDBConnectionString1255=== RUN TestResolveDBConnectionString/flag_wins1256=== PAUSE TestResolveDBConnectionString/flag_wins1257=== RUN TestResolveDBConnectionString/file_when_flag_empty1258=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1259=== RUN TestResolveDBConnectionString/missing_file_is_an_error1260=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1261=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1262=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1263=== RUN TestResolveDBConnectionString/nothing_configured1264=== PAUSE TestResolveDBConnectionString/nothing_configured1265=== CONT TestGenerateLandingPage1266--- PASS: TestGenerateLandingPage (0.00s)1267=== CONT TestGCTaskStore_GetEmpty1268--- PASS: TestGCTaskStore_GetEmpty (0.00s)1269=== CONT TestGracefulShutdownDrainsInflight12702026/11/09 12:14:39 INFO Starting HTTP server address=127.0.0.1:3904912712026/11/09 12:14:39 INFO Shutdown signal received, draining in-flight requests timeout=10s1272--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (0.87s)1273=== CONT TestGCTaskStore_ConflictDifferentParams1274--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1275=== CONT TestGCTaskStore_Fail1276--- PASS: TestGCTaskStore_Fail (0.00s)1277=== CONT TestService_healthCheckHandler1278--- PASS: TestReadProxyNarStreaming (0.56s)1279=== CONT TestGCTaskStore_DeduplicateSameParams1280--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1281=== CONT TestService_readinessHandler1282--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1283=== CONT TestGCTaskStore_StartNew1284--- PASS: TestGCTaskStore_StartNew (0.00s)1285=== CONT TestCommitRacingPendingCleanupKeepsObjects1286--- PASS: TestReadProxy404 (0.64s)1287=== CONT TestClientCADerivations12882026/11/09 12:14:39 INFO Received uploads request method=POST path=/api/pending_closures12892026/11/09 12:14:39 INFO Aborted multipart uploads count=0 kept=012902026/11/09 12:14:39 WARN Force mode enabled - objects will be deleted immediately without grace period12912026/11/09 12:14:39 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=012922026/11/09 12:14:39 INFO Vacuumed table table=pending_closures12932026/11/09 12:14:39 INFO Vacuumed table table=pending_objects12942026/11/09 12:14:39 INFO Vacuumed table table=multipart_uploads12952026/11/09 12:14:39 INFO Vacuumed table table=closures12962026/11/09 12:14:39 INFO Vacuumed table table=objects1297--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.62s)1298=== CONT TestPushWaitsForSweepHoldingRow12992026/11/09 12:14:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1300--- PASS: TestReadProxyContentNegotiation (0.65s)1301=== CONT TestGCEndsOnShutdown1302=== RUN TestGCEndsOnShutdown/before_the_run1303=== PAUSE TestGCEndsOnShutdown/before_the_run1304=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1305=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1306=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1307=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1308=== CONT TestSweepRechecksPendingAfterLocking1309--- PASS: TestGCSweepSkipsPendingObjects (0.68s)1310=== CONT TestDeleteClosuresRacingPins13112026/11/09 12:14:39 INFO Received uploads request method=POST path=/api/pending_closures13122026/11/09 12:14:39 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3Ljk2OWFhMTJmLWQ3ZjMtNGFmYS1iNmQ3LTllYWFlOGMzNTAzMngxNzk0MjI2NDc4NDM2MjQ5NjQw parts=121313--- PASS: TestSharedNarBothUploadsComplete (1.85s)1314=== CONT TestService_AuthMiddleware_OIDC1315--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.61s)1316=== CONT TestClientFallsBackToClosures13172026/11/09 12:14:39 INFO Received uploads request method=POST path=/api/pending_closures13182026/11/09 12:14:39 INFO Aborted multipart uploads count=0 kept=013192026/11/09 12:14:39 WARN Force mode enabled - objects will be deleted immediately without grace period13202026/11/09 12:14:39 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=013212026/11/09 12:14:39 INFO Vacuumed table table=pending_closures13222026/11/09 12:14:39 INFO Vacuumed table table=pending_objects13232026/11/09 12:14:39 INFO Vacuumed table table=multipart_uploads13242026/11/09 12:14:39 INFO Vacuumed table table=closures13252026/11/09 12:14:39 INFO Vacuumed table table=objects1326--- PASS: TestGCMetrics (0.43s)1327=== CONT TestClientPushesUseOnePush13282026/11/09 12:14:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36233/oidc13292026/11/09 12:14:39 INFO Aborted multipart uploads count=0 kept=013302026/11/09 12:14:39 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=013312026/11/09 12:14:39 INFO Vacuumed table table=pending_closures13322026/11/09 12:14:39 INFO Vacuumed table table=pending_objects13332026/11/09 12:14:39 INFO Vacuumed table table=multipart_uploads13342026/11/09 12:14:39 INFO Vacuumed table table=closures13352026/11/09 12:14:39 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"1336--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.69s)1337=== CONT TestCacheStatsHandler13382026/11/09 12:14:39 INFO Vacuumed table table=objects1339=== NAME TestNARDeduplicationMetadataUploadBug1340 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug723809744/001/store/3j10rhb70p18dng9y62qwxz7mlc6a9rw-file1.txt13412026/11/09 12:14:39 INFO Aborted multipart uploads count=0 kept=013422026/11/09 12:14:39 WARN Force mode enabled - objects will be deleted immediately without grace period13432026/11/09 12:14:39 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=013442026/11/09 12:14:39 INFO Vacuumed table table=pending_closures13452026/11/09 12:14:39 INFO Vacuumed table table=pending_objects13462026/11/09 12:14:39 INFO Vacuumed table table=multipart_uploads13472026/11/09 12:14:39 INFO Vacuumed table table=closures13482026/11/09 12:14:39 INFO Vacuumed table table=objects1349--- PASS: TestPushDedupSurvivesConcurrentGC (0.86s)1350=== CONT TestPinProtectsFromGC1351--- PASS: TestMetricsInventory (0.69s)1352=== CONT TestService_ReadScope_PublicByDefault13532026/11/09 12:14:39 INFO lead: acquired remote=192.0.2.1:123413542026/11/09 12:14:39 INFO lead: acquired remote=192.0.2.1:123413552026/11/09 12:14:39 INFO lead: released remote=192.0.2.1:12341356--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.71s)1357=== CONT TestService_RequireScope_OIDC13582026/11/09 12:14:39 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket68 days=21359--- PASS: TestEnsureAbortUploadsRule (0.72s)1360=== CONT TestClientSharedPathCommittedMidPush13612026/11/09 12:14:39 INFO lead: acquired remote=192.0.2.1:123413622026/11/09 12:14:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34515/oidc1363--- PASS: TestService_healthCheckHandler (0.68s)1364=== CONT TestCacheConfigHandler1365=== RUN TestCacheConfigHandler/full_config,_no_issuer1366=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1367=== RUN TestCacheConfigHandler/no_cache_url_configured1368=== PAUSE TestCacheConfigHandler/no_cache_url_configured1369=== RUN TestCacheConfigHandler/no_signing_keys1370=== PAUSE TestCacheConfigHandler/no_signing_keys1371=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1372=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1373=== CONT TestClientWithDependencies13742026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes13752026/11/09 12:14:40 WARN readiness check failed error="closed pool"1376--- PASS: TestService_readinessHandler (0.65s)1377=== CONT TestClientMultipleUploads13782026/11/09 12:14:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13792026/11/09 12:14:40 INFO Uploading 3j10rhb70p18dng9y62qwxz7mlc6a9rw-file1.txt (160B)13802026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"13812026/11/09 12:14:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13822026/11/09 12:14:40 WARN Failed to register uploaded object key=3j10rhb70p18dng9y62qwxz7mlc6a9rw.ls error="server returned 404: 404 page not found\n"13832026/11/09 12:14:40 INFO Signed narinfos id=1 count=113842026/11/09 12:14:40 INFO Uploading 1 narinfos13852026/11/09 12:14:40 INFO Received complete push request method=POST path=/api/pushes/1/complete13862026/11/09 12:14:40 WARN Failed to register uploaded object key=3j10rhb70p18dng9y62qwxz7mlc6a9rw.narinfo error="server returned 404: 404 page not found\n"13872026/11/09 12:14:40 INFO Completed push id=1 objects=3 duration=7.777744ms13882026/11/09 12:14:40 INFO Upload complete. (98ms)1389=== NAME TestNARDeduplicationMetadataUploadBug1390 metadata_upload_test.go:54: Retrieved narinfo from S3:1391 StorePath: /build/TestNARDeduplicationMetadataUploadBug723809744/001/store/3j10rhb70p18dng9y62qwxz7mlc6a9rw-file1.txt1392 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1393 Compression: zstd1394 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1395 NarSize: 1601396 References: 1397 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1398 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1399 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1400 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}14012026/11/09 12:14:40 INFO Aborted multipart uploads count=0 kept=014022026/11/09 12:14:40 INFO Received uploads request method=POST path=/api/pending_closures14032026/11/09 12:14:40 WARN Force mode enabled - objects will be deleted immediately without grace period14042026/11/09 12:14:40 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=014052026/11/09 12:14:40 INFO Vacuumed table table=pending_closures1406--- PASS: TestGCBugBareHashReferences (0.91s)14072026/11/09 12:14:40 INFO Vacuumed table table=pending_objects1408=== CONT TestClientIntegration14092026/11/09 12:14:40 INFO Vacuumed table table=multipart_uploads14102026/11/09 12:14:40 INFO Vacuumed table table=closures14112026/11/09 12:14:40 INFO Vacuumed table table=objects1412=== NAME TestNARDeduplicationMetadataUploadBug1413 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug723809744/001/store/nad463qgazfihwldl7rc6win4q561a2c-file2.txt14142026/11/09 12:14:40 INFO Aborted multipart uploads count=0 kept=014152026/11/09 12:14:40 WARN Force mode enabled - objects will be deleted immediately without grace period1416--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.73s)1417=== CONT TestService_AuthMiddleware_MTLSProxyHeader14182026/11/09 12:14:40 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=014192026/11/09 12:14:40 INFO Vacuumed table table=pending_closures14202026/11/09 12:14:40 INFO Vacuumed table table=pending_objects14212026/11/09 12:14:40 INFO Vacuumed table table=multipart_uploads14222026/11/09 12:14:40 INFO Vacuumed table table=closures14232026/11/09 12:14:40 INFO Vacuumed table table=objects1424--- PASS: TestSweepRechecksPendingAfterLocking (0.69s)1425=== CONT TestService_AuthMiddleware1426=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1427=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1428=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1429=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1430=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1431=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1432=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1433=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1434=== CONT TestClientErrorHandling1435=== RUN TestClientErrorHandling/InvalidStorePath1436=== PAUSE TestClientErrorHandling/InvalidStorePath1437=== RUN TestClientErrorHandling/InvalidAuthToken1438=== PAUSE TestClientErrorHandling/InvalidAuthToken1439=== RUN TestClientErrorHandling/ServerNotAvailable1440=== PAUSE TestClientErrorHandling/ServerNotAvailable1441=== CONT TestService_ReadAuthMiddleware1442=== NAME TestClientCADerivations1443 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations2791425249/001/store/ybv7vq3imphyffy8jvyks6r3b05mw4fn-ca-test14442026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes14452026/11/09 12:14:40 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14462026/11/09 12:14:40 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14472026/11/09 12:14:40 INFO Signed narinfos id=2 count=114482026/11/09 12:14:40 WARN Failed to register uploaded object key=nad463qgazfihwldl7rc6win4q561a2c.ls error="server returned 404: 404 page not found\n"14492026/11/09 12:14:40 INFO Uploading 1 narinfos1450--- PASS: TestCacheStatsHandler (0.30s)1451=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14522026/11/09 12:14:40 INFO Received complete push request method=POST path=/api/pushes/2/complete14532026/11/09 12:14:40 WARN Failed to register uploaded object key=nad463qgazfihwldl7rc6win4q561a2c.narinfo error="server returned 404: 404 page not found\n"14542026/11/09 12:14:40 INFO Completed push id=2 objects=3 duration=1.942941ms14552026/11/09 12:14:40 INFO Upload complete. (56ms)1456=== NAME TestNARDeduplicationMetadataUploadBug1457 metadata_upload_test.go:76: Retrieved narinfo from S3:1458 StorePath: /build/TestNARDeduplicationMetadataUploadBug723809744/001/store/nad463qgazfihwldl7rc6win4q561a2c-file2.txt1459 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1460 Compression: zstd1461 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1462 NarSize: 1601463 References: 1464 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1465 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1466 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1467 {"version":1,"root":{"type":"regular","size":44}}1468--- PASS: TestNARDeduplicationMetadataUploadBug (1.07s)1469=== CONT TestProxyWriteTimeout/narinfo1470=== CONT TestProxyWriteTimeout/unknown_size1471=== CONT TestProxyWriteTimeout/10_GiB_nar1472=== CONT TestProxyWriteTimeout/1_GiB_nar1473--- PASS: TestProxyWriteTimeout (0.09s)1474 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1475 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1476 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1477 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1478=== CONT TestIsValidCachePath/narinfo1479=== CONT TestIsValidCachePath/index.html1480=== CONT TestIsValidCachePath/short_hash1481=== CONT TestIsValidCachePath/wrong_extension1482=== CONT TestIsValidCachePath/leading_slash1483=== CONT TestIsValidCachePath/empty1484=== CONT TestIsValidCachePath/random_path1485=== CONT TestIsValidCachePath/invalid_char_u1486=== CONT TestIsValidCachePath/invalid_char_e1487=== CONT TestIsValidCachePath/traversal_in_middle1488=== CONT TestIsValidCachePath/traversal_parent1489=== CONT TestIsValidCachePath/nar_uncompressed1490=== CONT TestIsValidCachePath/nix-cache-info1491=== CONT TestIsValidCachePath/realisation1492=== CONT TestIsValidCachePath/log1493=== CONT TestIsValidCachePath/ls1494=== CONT TestIsValidCachePath/nar_zst1495=== CONT TestIsValidCachePath/nar_bz21496=== CONT TestIsValidCachePath/nar_xz1497=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1498--- PASS: TestIsValidCachePath (0.08s)1499 --- PASS: TestIsValidCachePath/narinfo (0.00s)1500 --- PASS: TestIsValidCachePath/index.html (0.00s)1501 --- PASS: TestIsValidCachePath/short_hash (0.00s)1502 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1503 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1504 --- PASS: TestIsValidCachePath/empty (0.00s)1505 --- PASS: TestIsValidCachePath/random_path (0.00s)1506 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1507 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1508 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1509 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1510 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1511 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1512 --- PASS: TestIsValidCachePath/realisation (0.00s)1513 --- PASS: TestIsValidCachePath/log (0.00s)1514 --- PASS: TestIsValidCachePath/ls (0.00s)1515 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1516 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1517 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1518 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1519=== NAME TestClientCADerivations1520 client_ca_test.go:139: Found 1 dependencies (including self)1521=== CONT TestPendingClosureWriteTimeout/empty1522=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1523--- PASS: TestService_ReadScope_PublicByDefault (0.30s)1524=== CONT TestPendingClosureWriteTimeout/670k_objects1525=== CONT TestPendingClosureWriteTimeout/400_objects1526=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15272026/11/09 12:14:40 INFO Received uploads request method=POST path=/1528=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15292026/11/09 12:14:40 INFO Received request for more parts method=POST path=/1530=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15312026/11/09 12:14:40 INFO Received uploads request method=POST path=/1532=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15332026/11/09 12:14:40 INFO Received complete multipart upload request method=POST path=/1534--- PASS: TestUploadHandlersRejectInvalidKeys (0.09s)1535 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1536 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1537 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1538 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1539=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1540=== RUN TestService_RequireScope_OIDC/builder_may_write1541=== PAUSE TestService_RequireScope_OIDC/builder_may_write1542=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1543=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1544=== RUN TestService_RequireScope_OIDC/ops_may_admin1545=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1546=== RUN TestService_RequireScope_OIDC/ops_may_not_write1547=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1548=== RUN TestService_RequireScope_OIDC/reader_may_not_write1549=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1550=== RUN TestService_RequireScope_OIDC/static_token_may_admin1551=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1552=== RUN TestService_RequireScope_OIDC/static_token_may_write1553=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1554=== RUN TestService_RequireScope_OIDC/reader_may_read1555=== PAUSE TestService_RequireScope_OIDC/reader_may_read1556=== RUN TestService_RequireScope_OIDC/writer_implies_read1557=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1558=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1559=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1560=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1561=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1562=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1563=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1564=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1565=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1566=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1567=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1568=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1569=== NAME TestPinProtectsFromGC1570 client_integration_test.go:778: Pinned store path: /build/TestPinProtectsFromGC1314972430/001/store/yncfvl2phyp1ra22qxv2g12xj018884r-pinned-file.txt1571 client_integration_test.go:779: Unpinned store path: /build/TestPinProtectsFromGC1314972430/001/store/nl5dld6cj0cajxwq7zwvaljpkv566fal-unpinned-file.txt15722026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes1573--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.22s)1574=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed15752026/11/09 12:14:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15762026/11/09 12:14:40 INFO Uploading ybv7vq3imphyffy8jvyks6r3b05mw4fn-ca-test (144B)15772026/11/09 12:14:40 WARN Failed to register uploaded object key=log/5s0bvv4vh3d9d9mfnifvf9575gghllb5-ca-test.drv error="server returned 404: 404 page not found\n"15782026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"15792026/11/09 12:14:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15802026/11/09 12:14:40 WARN Failed to register uploaded object key=ybv7vq3imphyffy8jvyks6r3b05mw4fn.ls error="server returned 404: 404 page not found\n"15812026/11/09 12:14:40 INFO Signed narinfos id=1 count=115822026/11/09 12:14:40 INFO Uploading 1 narinfos1583=== NAME TestClientMultipleUploads1584 client_integration_test.go:405: Created store path 0: /build/TestClientMultipleUploads1618966391/001/store/sij7y30fdg7qsa9jwd2cf9vfilinm2w0-test-file-0.txt15852026/11/09 12:14:40 INFO Received complete push request method=POST path=/api/pushes/1/complete15862026/11/09 12:14:40 WARN Failed to register uploaded object key=ybv7vq3imphyffy8jvyks6r3b05mw4fn.narinfo error="server returned 404: 404 page not found\n"15872026/11/09 12:14:40 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1588--- PASS: TestService_AuthMiddleware (0.21s)1589=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed15902026/11/09 12:14:40 INFO Completed push id=1 objects=4 duration=7.582404ms15912026/11/09 12:14:40 INFO Upload complete. (110ms)1592=== NAME TestClientCADerivations1593 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations2791425249/001/store/ybv7vq3imphyffy8jvyks6r3b05mw4fn-ca-test1594 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1595 Compression: zstd1596 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1597 NarSize: 1441598 References: 1599 Deriver: /build/TestClientCADerivations2791425249/001/store/5s0bvv4vh3d9d9mfnifvf9575gghllb5-ca-test.drv1600 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1601 client_ca_test.go:185: Checking for realisation files in S3...16022026/11/09 12:14:40 INFO Received uploads request method=POST path=/api/pending_closures1603 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1604 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache16052026/11/09 12:14:40 INFO Received uploads request method=POST path=/api/pending_closures16062026/11/09 12:14:40 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16072026/11/09 12:14:40 INFO Uploading zw6bf935i5iw924bdps5f0vlb3faiz9j-shared-dep (136B)16082026/11/09 12:14:40 INFO Uploading rkiq0jmxxv5wa496iswnxj1jkx3an87d-a (216B)1609=== NAME TestClientIntegration1610 client_integration_test.go:291: Created store path: /build/TestClientIntegration2782830756/002/store/sfi67rnqrxq9l2w1bgw648pgzwj32nfq-test-file.txt16112026/11/09 12:14:40 WARN Failed to register uploaded object key=b10i3nny024yzw2x2mpbr06nk4d7lkln.ls error="server returned 404: 404 page not found\n"16122026/11/09 12:14:40 WARN Failed to register uploaded object key=rkiq0jmxxv5wa496iswnxj1jkx3an87d.ls error="server returned 404: 404 page not found\n"16132026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16142026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes1615--- PASS: TestService_ReadAuthMiddleware (0.21s)16162026/11/09 12:14:40 WARN Failed to register uploaded object key=zw6bf935i5iw924bdps5f0vlb3faiz9j.ls error="server returned 404: 404 page not found\n"1617=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed16182026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/19lnrn062f89qyb9yhz4ss196jp6rysj0kfkwba5a9iamic1fj9c.nar.zst error="server returned 404: 404 page not found\n"16192026/11/09 12:14:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16202026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes16212026/11/09 12:14:40 INFO Signed narinfos id=1 count=216222026/11/09 12:14:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16232026/11/09 12:14:40 INFO Signed narinfos id=2 count=216242026/11/09 12:14:40 INFO Uploading 4 narinfos16252026/11/09 12:14:40 WARN Failed to register uploaded object key=rkiq0jmxxv5wa496iswnxj1jkx3an87d.narinfo error="server returned 404: 404 page not found\n"16262026/11/09 12:14:40 WARN Failed to register uploaded object key=zw6bf935i5iw924bdps5f0vlb3faiz9j.narinfo error="server returned 404: 404 page not found\n"16272026/11/09 12:14:40 WARN Failed to register uploaded object key=b10i3nny024yzw2x2mpbr06nk4d7lkln.narinfo error="server returned 404: 404 page not found\n"16282026/11/09 12:14:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16292026/11/09 12:14:40 WARN Failed to register uploaded object key=zw6bf935i5iw924bdps5f0vlb3faiz9j.narinfo error="server returned 404: 404 page not found\n"1630=== NAME TestClientWithDependencies1631 client_integration_test.go:660: Built derivation: /build/TestClientWithDependencies1290761898/001/store/mlk008q6gz6zcl5bhnrdpaagr2wpd2gz-test-script1632=== NAME TestClientMultipleUploads1633 client_integration_test.go:405: Created store path 1: /build/TestClientMultipleUploads1618966391/001/store/75pnz5mfhnrn2xvcv5q4s7rk7m2206hj-test-file-1.txt16342026/11/09 12:14:40 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16352026/11/09 12:14:40 INFO Uploading 8b8sj72ybs8ay5ryajwq1d28x734jysq-b (216B)16362026/11/09 12:14:40 INFO Uploading svzkldip425zl47r9wy19lqph423kysa-shared-dep (136B)16372026/11/09 12:14:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16382026/11/09 12:14:40 INFO Uploading yncfvl2phyp1ra22qxv2g12xj018884r-pinned-file.txt (128B)16392026/11/09 12:14:40 INFO Completed upload id=1 objects=6 duration=8.739634ms16402026/11/09 12:14:40 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16412026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/17wdz84mg9h895nc50imbjjrwzs5q3nn3gphafiqvglzshlkql3g.nar.zst error="server returned 404: 404 page not found\n"16422026/11/09 12:14:40 INFO Completed upload id=2 objects=6 duration=2.442731ms16432026/11/09 12:14:40 WARN Failed to register uploaded object key=1v6f3zxsrh1nvdp8bw18ny10cjswplm2.ls error="server returned 404: 404 page not found\n"16442026/11/09 12:14:40 INFO Upload complete. (88ms)16452026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16462026/11/09 12:14:40 WARN Failed to register uploaded object key=svzkldip425zl47r9wy19lqph423kysa.ls error="server returned 404: 404 page not found\n"16472026/11/09 12:14:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16482026/11/09 12:14:40 WARN Failed to register uploaded object key=8b8sj72ybs8ay5ryajwq1d28x734jysq.ls error="server returned 404: 404 page not found\n"16492026/11/09 12:14:40 INFO Signed narinfos id=1 count=316502026/11/09 12:14:40 INFO Uploading 3 narinfos1651=== NAME TestClientFallsBackToClosures1652 client_pushes_test.go:112: Retrieved narinfo from S3:1653 StorePath: /build/TestClientFallsBackToClosures2786336019/001/store/zw6bf935i5iw924bdps5f0vlb3faiz9j-shared-dep1654 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1655 Compression: zstd1656 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821657 NarSize: 1361658 References: 16592026/11/09 12:14:40 WARN Failed to register uploaded object key=yncfvl2phyp1ra22qxv2g12xj018884r.ls error="server returned 404: 404 page not found\n"1660 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n16612026/11/09 12:14:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16622026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16632026/11/09 12:14:40 INFO Signed narinfos id=1 count=116642026/11/09 12:14:40 INFO Uploading 1 narinfos1665 client_pushes_test.go:112: Retrieved narinfo from S3:1666 StorePath: /build/TestClientFallsBackToClosures2786336019/001/store/rkiq0jmxxv5wa496iswnxj1jkx3an87d-a1667 URL: nar/19lnrn062f89qyb9yhz4ss196jp6rysj0kfkwba5a9iamic1fj9c.nar.zst1668 Compression: zstd1669 NarHash: sha256:19lnrn062f89qyb9yhz4ss196jp6rysj0kfkwba5a9iamic1fj9c16702026/11/09 12:14:40 WARN Failed to register uploaded object key=1v6f3zxsrh1nvdp8bw18ny10cjswplm2.narinfo error="server returned 404: 404 page not found\n"1671 NarSize: 21616722026/11/09 12:14:40 WARN Failed to register uploaded object key=svzkldip425zl47r9wy19lqph423kysa.narinfo error="server returned 404: 404 page not found\n"1673 References: /build/TestClientFallsBackToClosures2786336019/001/store/zw6bf935i5iw924bdps5f0vlb3faiz9j-shared-dep1674 CA: text:sha256:0xh26vv130k21b7yrlbgj7hqizz26q5apkxh5mi3axjlmrywhfxy1675 client_pushes_test.go:112: Retrieved narinfo from S3:1676 StorePath: /build/TestClientFallsBackToClosures2786336019/001/store/b10i3nny024yzw2x2mpbr06nk4d7lkln-b1677 URL: nar/19lnrn062f89qyb9yhz4ss196jp6rysj0kfkwba5a9iamic1fj9c.nar.zst1678 Compression: zstd1679 NarHash: sha256:19lnrn062f89qyb9yhz4ss196jp6rysj0kfkwba5a9iamic1fj9c1680 NarSize: 2161681 References: /build/TestClientFallsBackToClosures2786336019/001/store/zw6bf935i5iw924bdps5f0vlb3faiz9j-shared-dep1682 CA: text:sha256:0xh26vv130k21b7yrlbgj7hqizz26q5apkxh5mi3axjlmrywhfxy16832026/11/09 12:14:40 INFO Received complete push request method=POST path=/api/pushes/1/complete16842026/11/09 12:14:40 WARN Failed to register uploaded object key=yncfvl2phyp1ra22qxv2g12xj018884r.narinfo error="server returned 404: 404 page not found\n"16852026/11/09 12:14:40 INFO Received complete push request method=POST path=/api/pushes/1/complete16862026/11/09 12:14:40 WARN Failed to register uploaded object key=8b8sj72ybs8ay5ryajwq1d28x734jysq.narinfo error="server returned 404: 404 page not found\n"1687--- PASS: TestClientFallsBackToClosures (0.94s)1688=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost16892026/11/09 12:14:40 INFO Completed push id=1 objects=8 duration=6.853193ms16902026/11/09 12:14:40 INFO Upload complete. (91ms)16912026/11/09 12:14:40 INFO Completed push id=1 objects=3 duration=7.128063ms16922026/11/09 12:14:40 INFO Upload complete. (87ms)1693=== NAME TestClientPushesUseOnePush1694 client_pushes_test.go:97: Retrieved narinfo from S3:1695 StorePath: /build/TestClientPushesUseOnePush3208062759/001/store/svzkldip425zl47r9wy19lqph423kysa-shared-dep1696 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1697 Compression: zstd1698 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821699 NarSize: 1361700 References: 1701 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n17022026/11/09 12:14:40 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"17032026/11/09 12:14:40 WARN mTLS auth: bound subjects configured but subject DN unavailable17042026/11/09 12:14:40 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1705--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.23s)1706=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1707=== NAME TestClientPushesUseOnePush1708 client_pushes_test.go:97: Retrieved narinfo from S3:1709 StorePath: /build/TestClientPushesUseOnePush3208062759/001/store/1v6f3zxsrh1nvdp8bw18ny10cjswplm2-a1710 URL: nar/17wdz84mg9h895nc50imbjjrwzs5q3nn3gphafiqvglzshlkql3g.nar.zst1711 Compression: zstd1712 NarHash: sha256:17wdz84mg9h895nc50imbjjrwzs5q3nn3gphafiqvglzshlkql3g1713 NarSize: 2161714 References: /build/TestClientPushesUseOnePush3208062759/001/store/svzkldip425zl47r9wy19lqph423kysa-shared-dep1715 CA: text:sha256:1bzp7sghqdk1ji04ilz6zcsjdgnlh535yf0z24njrksd3df50s7a1716 client_pushes_test.go:97: Retrieved narinfo from S3:1717 StorePath: /build/TestClientPushesUseOnePush3208062759/001/store/8b8sj72ybs8ay5ryajwq1d28x734jysq-b1718 URL: nar/17wdz84mg9h895nc50imbjjrwzs5q3nn3gphafiqvglzshlkql3g.nar.zst1719 Compression: zstd1720 NarHash: sha256:17wdz84mg9h895nc50imbjjrwzs5q3nn3gphafiqvglzshlkql3g1721 NarSize: 2161722 References: /build/TestClientPushesUseOnePush3208062759/001/store/svzkldip425zl47r9wy19lqph423kysa-shared-dep1723 CA: text:sha256:1bzp7sghqdk1ji04ilz6zcsjdgnlh535yf0z24njrksd3df50s7a17242026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes1725--- PASS: TestClientPushesUseOnePush (0.88s)1726=== CONT TestParseSingleRange/none1727=== CONT TestParseSingleRange/start_far_past_EOF1728=== CONT TestParseSingleRange/start_past_EOF1729=== CONT TestParseSingleRange/single_byte1730=== CONT TestParseSingleRange/suffix_exceeds_size1731=== CONT TestParseSingleRange/suffix1732=== CONT TestParseSingleRange/end_clamped_to_size1733=== CONT TestParseSingleRange/open-ended1734=== CONT TestParseSingleRange/closed17352026/11/09 12:14:40 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)1736=== CONT TestParseSingleRange/malformed_end_before_start17372026/11/09 12:14:40 INFO Uploading sqhr6481kh9z0k0044bw4mk9ybk1s9mb-shared-dep (136B)1738=== CONT TestParseSingleRange/malformed_both_empty17392026/11/09 12:14:40 INFO Uploading 7bi89gynqphf5wfb7qfwwalr85cp820k-top (224B)1740=== CONT TestParseSingleRange/malformed_no_dash1741=== CONT TestParseSingleRange/multi-range_ignored1742=== CONT TestParseSingleRange/unknown_unit1743--- PASS: TestParseSingleRange (0.09s)1744 --- PASS: TestParseSingleRange/none (0.00s)1745 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1746 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1747 --- PASS: TestParseSingleRange/single_byte (0.00s)1748 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1749 --- PASS: TestParseSingleRange/suffix (0.00s)1750 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1751 --- PASS: TestParseSingleRange/open-ended (0.00s)1752 --- PASS: TestParseSingleRange/closed (0.00s)1753 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1754 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1755 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1756 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1757 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1758=== CONT TestIsValidUploadKey/narinfo1759=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1760=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1761=== CONT TestIsValidUploadKey/index.html1762=== CONT TestIsValidUploadKey/nix-cache-info1763=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1764=== CONT TestIsValidUploadKey/realisation_plus_in_output1765=== CONT TestIsValidUploadKey/realisation1766=== CONT TestIsValidUploadKey/build_log_equals1767=== CONT TestIsValidUploadKey/unknown_type1768=== NAME TestClientWithDependencies1769 client_integration_test.go:662: Found 1 dependencies (including self)1770=== CONT TestIsValidUploadKey/build_log_question_mark1771=== CONT TestIsValidUploadKey/empty_key1772=== CONT TestIsValidUploadKey/nar_plain1773=== CONT TestIsValidUploadKey/absolute1774=== CONT TestIsValidUploadKey/nar_xz1775=== CONT TestIsValidUploadKey/traversal_nar1776=== CONT TestIsValidUploadKey/nar_zst1777=== CONT TestIsValidUploadKey/traversal1778=== CONT TestIsValidUploadKey/build_log_home-manager_file1779=== CONT TestIsValidUploadKey/build_log_plus_in_name1780=== CONT TestIsValidUploadKey/build_log1781=== CONT TestIsValidUploadKey/listing1782--- PASS: TestIsValidUploadKey (0.10s)1783 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1784 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1785 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1786 --- PASS: TestIsValidUploadKey/index.html (0.00s)1787 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1788 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1789 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1790 --- PASS: TestIsValidUploadKey/realisation (0.00s)1791 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1792 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1793 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1794 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1795 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1796 --- PASS: TestIsValidUploadKey/absolute (0.00s)1797 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1798 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1799 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1800 --- PASS: TestIsValidUploadKey/traversal (0.00s)1801 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1802 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1803 --- PASS: TestIsValidUploadKey/build_log (0.00s)1804 --- PASS: TestIsValidUploadKey/listing (0.00s)1805=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18062026/11/09 12:14:40 INFO Received uploads request method=POST path=/18072026/11/09 12:14:40 WARN Failed to register uploaded object key=sqhr6481kh9z0k0044bw4mk9ybk1s9mb.ls error="server returned 404: 404 page not found\n"18082026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18092026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/1dgixagcsrwjh632na0y7zb4cvka5q9zrv31m2j7xlr2j0v05myx.nar.zst error="server returned 404: 404 page not found\n"18102026/11/09 12:14:40 WARN Failed to register uploaded object key=7bi89gynqphf5wfb7qfwwalr85cp820k.ls error="server returned 404: 404 page not found\n"18112026/11/09 12:14:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18122026/11/09 12:14:40 INFO Signed narinfos id=1 count=218132026/11/09 12:14:40 INFO Uploading 2 narinfos1814=== NAME TestClientMultipleUploads1815 client_integration_test.go:405: Created store path 2: /build/TestClientMultipleUploads1618966391/001/store/1yb6kxr3ni6qdx29jx5w77xylgcic96s-test-file-2.txt18162026/11/09 12:14:40 INFO Received uploads request method=POST path=/api/pending_closures18172026/11/09 12:14:40 INFO Received complete push request method=POST path=/api/pushes/1/complete18182026/11/09 12:14:40 WARN Failed to register uploaded object key=7bi89gynqphf5wfb7qfwwalr85cp820k.narinfo error="server returned 404: 404 page not found\n"18192026/11/09 12:14:40 WARN Failed to register uploaded object key=sqhr6481kh9z0k0044bw4mk9ybk1s9mb.narinfo error="server returned 404: 404 page not found\n"18202026/11/09 12:14:40 INFO Completed push id=1 objects=6 duration=7.059053ms18212026/11/09 12:14:40 INFO Upload complete. (82ms)1822=== NAME TestClientSharedPathCommittedMidPush1823 client_integration_test.go:727: Retrieved narinfo from S3:1824 StorePath: /build/TestClientSharedPathCommittedMidPush2307966501/001/store/sqhr6481kh9z0k0044bw4mk9ybk1s9mb-shared-dep1825 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1826 Compression: zstd1827 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821828 NarSize: 1361829 References: 1830 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1831 client_integration_test.go:727: Retrieved narinfo from S3:1832 StorePath: /build/TestClientSharedPathCommittedMidPush2307966501/001/store/7bi89gynqphf5wfb7qfwwalr85cp820k-top1833 URL: nar/1dgixagcsrwjh632na0y7zb4cvka5q9zrv31m2j7xlr2j0v05myx.nar.zst1834 Compression: zstd1835 NarHash: sha256:1dgixagcsrwjh632na0y7zb4cvka5q9zrv31m2j7xlr2j0v05myx1836 NarSize: 2241837 References: /build/TestClientSharedPathCommittedMidPush2307966501/001/store/sqhr6481kh9z0k0044bw4mk9ybk1s9mb-shared-dep1838 CA: text:sha256:0zigvh53znfsk5h7jvhvhzr30ybbgbm1y6fkacyaz6insivbgb7k1839--- PASS: TestClientSharedPathCommittedMidPush (0.49s)1840=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18412026/11/09 12:14:40 INFO Received request for more parts method=POST path=/18422026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes18432026/11/09 12:14:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18442026/11/09 12:14:40 INFO Uploading sfi67rnqrxq9l2w1bgw648pgzwj32nfq-test-file.txt (152B)18452026/11/09 12:14:40 WARN Failed to register uploaded object key=sfi67rnqrxq9l2w1bgw648pgzwj32nfq.ls error="server returned 404: 404 page not found\n"18462026/11/09 12:14:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18472026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18482026/11/09 12:14:40 INFO Signed narinfos id=1 count=118492026/11/09 12:14:40 INFO Uploading 1 narinfos18502026/11/09 12:14:40 INFO Received complete push request method=POST path=/api/pushes/1/complete18512026/11/09 12:14:40 WARN Failed to register uploaded object key=sfi67rnqrxq9l2w1bgw648pgzwj32nfq.narinfo error="server returned 404: 404 page not found\n"18522026/11/09 12:14:40 INFO Completed push id=1 objects=3 duration=6.923073ms18532026/11/09 12:14:40 INFO Upload complete. (77ms)1854=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18552026/11/09 12:14:40 INFO Received complete multipart upload request method=POST path=/18562026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes18572026/11/09 12:14:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18582026/11/09 12:14:40 INFO Uploading nl5dld6cj0cajxwq7zwvaljpkv566fal-unpinned-file.txt (128B)18592026/11/09 12:14:40 WARN Failed to register uploaded object key=nl5dld6cj0cajxwq7zwvaljpkv566fal.ls error="server returned 404: 404 page not found\n"18602026/11/09 12:14:40 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign18612026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"18622026/11/09 12:14:40 INFO Signed narinfos id=2 count=118632026/11/09 12:14:40 INFO Uploading 1 narinfos18642026/11/09 12:14:40 INFO Received complete push request method=POST path=/api/pushes/2/complete18652026/11/09 12:14:40 WARN Failed to register uploaded object key=nl5dld6cj0cajxwq7zwvaljpkv566fal.narinfo error="server returned 404: 404 page not found\n"18662026/11/09 12:14:40 INFO Completed push id=2 objects=3 duration=2.543271ms18672026/11/09 12:14:40 INFO Upload complete. (63ms)18682026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes18692026/11/09 12:14:40 INFO All 1 paths already cached1870=== NAME TestClientIntegration1871 client_integration_test.go:317: Retrieved narinfo from S3:1872 StorePath: /build/TestClientIntegration2782830756/002/store/sfi67rnqrxq9l2w1bgw648pgzwj32nfq-test-file.txt1873 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1874 Compression: zstd1875 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11876 NarSize: 1521877 References: 1878 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk118792026/11/09 12:14:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18802026/11/09 12:14:40 INFO Uploading mlk008q6gz6zcl5bhnrdpaagr2wpd2gz-test-script (136B)1881 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1882 client_integration_test.go:318: Decompressed .ls content (64 bytes):1883 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}18842026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes18852026/11/09 12:14:40 WARN Failed to register uploaded object key=mlk008q6gz6zcl5bhnrdpaagr2wpd2gz.ls error="server returned 404: 404 page not found\n"18862026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18872026/11/09 12:14:40 WARN Failed to register uploaded object key=log/6kv8xn0xzm0biiyygq7yy9lk9akkksj0-test-script.drv error="server returned 404: 404 page not found\n"18882026/11/09 12:14:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18892026/11/09 12:14:40 INFO Signed narinfos id=1 count=118902026/11/09 12:14:40 INFO Uploading 1 narinfos18912026/11/09 12:14:40 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18922026/11/09 12:14:40 INFO Uploading 75pnz5mfhnrn2xvcv5q4s7rk7m2206hj-test-file-1.txt (160B)18932026/11/09 12:14:40 INFO Uploading sij7y30fdg7qsa9jwd2cf9vfilinm2w0-test-file-0.txt (160B)18942026/11/09 12:14:40 INFO Uploading 1yb6kxr3ni6qdx29jx5w77xylgcic96s-test-file-2.txt (160B)18952026/11/09 12:14:40 INFO Received complete push request method=POST path=/api/pushes/1/complete18962026/11/09 12:14:40 WARN Failed to register uploaded object key=mlk008q6gz6zcl5bhnrdpaagr2wpd2gz.narinfo error="server returned 404: 404 page not found\n"18972026/11/09 12:14:40 WARN Failed to register uploaded object key=75pnz5mfhnrn2xvcv5q4s7rk7m2206hj.ls error="server returned 404: 404 page not found\n"18982026/11/09 12:14:40 WARN Failed to register uploaded object key=sij7y30fdg7qsa9jwd2cf9vfilinm2w0.ls error="server returned 404: 404 page not found\n"18992026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"19002026/11/09 12:14:40 WARN Failed to register uploaded object key=1yb6kxr3ni6qdx29jx5w77xylgcic96s.ls error="server returned 404: 404 page not found\n"1901=== CONT TestPush_RejectsBadRequests/no_roots19022026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"19032026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes1904=== CONT TestPush_RejectsBadRequests/bad_root19052026/11/09 12:14:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19062026/11/09 12:14:40 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"19072026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes1908=== CONT TestPush_RejectsBadRequests/root_not_in_objects19092026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes1910=== CONT TestPush_RejectsBadRequests/no_objects19112026/11/09 12:14:40 INFO Signed narinfos id=1 count=319122026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes1913=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows19142026/11/09 12:14:40 INFO Uploading 3 narinfos1915--- PASS: TestPush_RejectsBadRequests (0.70s)1916 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1917 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1918 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1919 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)19202026/11/09 12:14:40 INFO Completed push id=1 objects=4 duration=7.080793ms19212026/11/09 12:14:40 WARN Failed to register uploaded object key=75pnz5mfhnrn2xvcv5q4s7rk7m2206hj.narinfo error="server returned 404: 404 page not found\n"19222026/11/09 12:14:40 INFO Received complete push request method=POST path=/api/pushes/1/complete19232026/11/09 12:14:40 WARN Failed to register uploaded object key=1yb6kxr3ni6qdx29jx5w77xylgcic96s.narinfo error="server returned 404: 404 page not found\n"19242026/11/09 12:14:40 INFO Upload complete. (76ms)19252026/11/09 12:14:40 WARN Failed to register uploaded object key=sij7y30fdg7qsa9jwd2cf9vfilinm2w0.narinfo error="server returned 404: 404 page not found\n"1926=== NAME TestClientWithDependencies1927 client_integration_test.go:664: Skipping nix copy test - isolated store (/build/TestClientWithDependencies1290761898/001/store) requires matching store prefix1928=== NAME TestClientCADerivations1929 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1930 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1931 error: binary cache 's3://bucket73?endpoint=http://localhost:43951®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations2791425249/001/store'1932 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 119332026/11/09 12:14:40 INFO Completed push id=1 objects=9 duration=5.961303ms19342026/11/09 12:14:40 INFO Upload complete. (75ms)1935=== NAME TestClientMultipleUploads1936 client_integration_test.go:416: Uploaded 3 paths in 117.981769ms1937--- PASS: TestClientWithDependencies (0.56s)1938=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1939--- PASS: TestClientCADerivations (1.17s)1940=== CONT TestServerTLSConfig/no_client_CA1941=== CONT TestServerTLSConfig/not_a_PEM_file1942=== CONT TestServerTLSConfig/missing_CA_file1943--- PASS: TestServerTLSConfig (0.00s)1944 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1945 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1946 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1947=== CONT TestResolveDBConnectionString/flag_wins1948=== CONT TestResolveDBConnectionString/PGHOST_allows_empty19492026/11/09 12:14:40 INFO Received uploads request method=POST path=/api/pending_closures1950=== CONT TestResolveDBConnectionString/nothing_configured1951=== CONT TestResolveDBConnectionString/missing_file_is_an_error1952=== CONT TestResolveDBConnectionString/file_when_flag_empty1953=== CONT TestGCEndsOnShutdown/before_the_run1954--- PASS: TestResolveDBConnectionString (0.00s)1955 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1956 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1957 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1958 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1959 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1960--- PASS: TestClientMultipleUploads (0.55s)1961=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19622026/11/09 12:14:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures19632026/11/09 12:14:40 INFO Garbage collection started19642026/11/09 12:14:40 INFO Received uploads request method=POST path=/api/pending_closures1965--- PASS: TestPushWaitsForSweepHoldingRow (1.14s)1966=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19672026/11/09 12:14:40 INFO Aborted multipart uploads count=0 kept=019682026/11/09 12:14:40 INFO Received uploads request method=POST path=/api/pending_closures19692026/11/09 12:14:40 WARN Force mode enabled - objects will be deleted immediately without grace period19702026/11/09 12:14:40 INFO Received uploads request method=POST path=/api/pending_closures19712026/11/09 12:14:40 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=019722026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes19732026/11/09 12:14:40 INFO Vacuumed table table=pending_closures19742026/11/09 12:14:40 INFO Received uploads request method=POST path=/api/pending_closures19752026/11/09 12:14:40 INFO Object in database but missing from S3 key=sfi67rnqrxq9l2w1bgw648pgzwj32nfq.ls19762026/11/09 12:14:40 WARN Found objects in DB but missing from S3, will re-upload count=119772026/11/09 12:14:40 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19782026/11/09 12:14:40 INFO Vacuumed table table=pending_objects19792026/11/09 12:14:40 INFO Vacuumed table table=multipart_uploads19802026/11/09 12:14:40 INFO Vacuumed table table=closures19812026/11/09 12:14:40 INFO Received complete push request method=POST path=/api/pushes/2/complete19822026/11/09 12:14:40 WARN Failed to register uploaded object key=sfi67rnqrxq9l2w1bgw648pgzwj32nfq.ls error="server returned 404: 404 page not found\n"19832026/11/09 12:14:40 INFO Vacuumed table table=objects19842026/11/09 12:14:40 INFO Completed push id=2 objects=3 duration=2.358241ms19852026/11/09 12:14:40 INFO Upload complete. (56ms)1986=== NAME TestClientIntegration1987 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1988 client_integration_test.go:335: Decompressed .ls content (49 bytes):1989 {"version":1,"root":{"type":"regular","size":39}}19902026/11/09 12:14:40 INFO Received push request method=POST path=/api/pushes19912026/11/09 12:14:40 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19922026/11/09 12:14:40 INFO Received complete push request method=POST path=/api/pushes/3/complete19932026/11/09 12:14:40 WARN Failed to register uploaded object key=sfi67rnqrxq9l2w1bgw648pgzwj32nfq.ls error="server returned 404: 404 page not found\n"19942026/11/09 12:14:40 INFO Completed push id=3 objects=3 duration=2.286391ms19952026/11/09 12:14:40 INFO Upload complete. (173ms)1996 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1997 client_integration_test.go:352: Decompressed .ls content (49 bytes):1998 {"version":1,"root":{"type":"regular","size":39}}1999 client_integration_test.go:363: Testing garbage collection...20002026/11/09 12:14:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures20012026/11/09 12:14:40 INFO Garbage collection started20022026/11/09 12:14:40 INFO Aborted multipart uploads count=0 kept=020032026/11/09 12:14:40 INFO Received uploads request method=POST path=/api/pending_closures20042026/11/09 12:14:40 WARN Force mode enabled - objects will be deleted immediately without grace period2005=== NAME TestOrphanedObjectsGCStressTest2006 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains20072026/11/09 12:14:40 INFO Aborted multipart uploads count=0 kept=020082026/11/09 12:14:40 WARN Force mode enabled - objects will be deleted immediately without grace period20092026/11/09 12:14:40 INFO lead: released remote=192.0.2.1:12342010--- PASS: TestLeadEndsOnShutdown (1.76s)2011=== CONT TestCacheConfigHandler/full_config,_no_issuer2012=== CONT TestCacheConfigHandler/no_signing_keys2013=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2014=== CONT TestCacheConfigHandler/no_cache_url_configured2015--- PASS: TestCacheConfigHandler (0.00s)2016 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2017 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2018 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2019 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2020=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2021=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20222026/11/09 12:14:40 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]2023=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2024=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20252026/11/09 12:14:40 WARN Authentication failed token_preview=eyJhbGciOi...lWLF4FcEVw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2026=== CONT TestClientErrorHandling/InvalidStorePath2027=== CONT TestClientErrorHandling/ServerNotAvailable2028--- PASS: TestService_AuthMiddleware_OIDC (0.70s)2029 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2030 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2031 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2032 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2033=== NAME TestOrphanedObjectsGCStressTest2034 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion20352026/11/09 12:14:40 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=020362026/11/09 12:14:40 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=020372026/11/09 12:14:40 INFO Vacuumed table table=pending_closures20382026/11/09 12:14:41 INFO Vacuumed table table=pending_objects20392026/11/09 12:14:41 INFO Aborted multipart uploads count=0 kept=020402026/11/09 12:14:41 INFO Vacuumed table table=multipart_uploads20412026/11/09 12:14:41 INFO Vacuumed table table=closures2042--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2043 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.75s)2044 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.73s)2045=== CONT TestClientErrorHandling/InvalidAuthToken2046=== CONT TestService_RequireScope_OIDC/builder_may_write20472026/11/09 12:14:41 INFO Vacuumed table table=objects2048=== CONT TestService_RequireScope_OIDC/reader_may_read20492026/11/09 12:14:41 INFO Vacuumed table table=pending_closures2050=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2051=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20522026/11/09 12:14:41 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]2053=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2054=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2055=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2056=== CONT TestService_RequireScope_OIDC/writer_implies_read2057=== CONT TestService_RequireScope_OIDC/reader_may_not_write2058=== CONT TestService_RequireScope_OIDC/ops_may_admin2059=== CONT TestService_RequireScope_OIDC/static_token_may_write2060=== CONT TestService_RequireScope_OIDC/ops_may_not_write2061=== CONT TestService_RequireScope_OIDC/static_token_may_admin2062=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2063--- PASS: TestService_RequireScope_OIDC (0.33s)2064 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2065 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2066 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2067 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2068 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2069 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2070 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2071 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2072 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2073 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2074 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2075 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2076 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2077 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)20782026/11/09 12:14:41 WARN Force mode enabled - objects will be deleted immediately without grace period20792026/11/09 12:14:41 INFO Vacuumed table table=pending_objects20802026/11/09 12:14:41 INFO Vacuumed table table=multipart_uploads20812026/11/09 12:14:41 INFO Vacuumed table table=closures20822026/11/09 12:14:41 INFO Vacuumed table table=objects20832026/11/09 12:14:41 INFO Aborted multipart uploads count=0 kept=020842026/11/09 12:14:41 WARN Force mode enabled - objects will be deleted immediately without grace period20852026/11/09 12:14:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20862026/11/09 12:14:41 INFO Received uploads request method=POST path=/api/pending_closures20872026/11/09 12:14:41 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:43951/bucket103/?delete=\": context canceled"2088--- PASS: TestGCEndsOnShutdown (0.00s)2089 --- PASS: TestGCEndsOnShutdown/before_the_run (0.43s)2090 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.45s)2091 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.46s)20922026/11/09 12:14:41 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LjdiODhlY2M0LTZlMWEtNGU0Yi05ZDllLTdkZWQyMjkxYjFkYngxNzk0MjI2NDgwNTc1NDIwNDgx parts=1020932026/11/09 12:14:41 INFO Aborted multipart uploads count=0 kept=020942026/11/09 12:14:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete20952026/11/09 12:14:41 WARN Force mode enabled - objects will be deleted immediately without grace period20962026/11/09 12:14:41 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=020972026/11/09 12:14:41 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/present20982026/11/09 12:14:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20992026/11/09 12:14:41 INFO Completed upload id=1 objects=3 duration=20.069518ms21002026/11/09 12:14:41 INFO Vacuumed table table=pending_closures21012026/11/09 12:14:41 INFO Vacuumed table table=pending_objects21022026/11/09 12:14:41 INFO Vacuumed table table=multipart_uploads21032026/11/09 12:14:41 INFO Vacuumed table table=closures21042026/11/09 12:14:41 INFO Vacuumed table table=objects21052026/11/09 12:14:41 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LjJjZWRjYTMwLTQzNzQtNDg2ZS1hNTczLTQwMGFjZGE2ZjQ0NHgxNzk0MjI2NDgwNTk0MjU0Mjc4 parts=1021062026/11/09 12:14:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21072026/11/09 12:14:41 INFO Completed upload id=1 objects=3 duration=4.713502ms2108--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2109 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.47s)2110 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.54s)21112026/11/09 12:14:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21122026/11/09 12:14:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21132026/11/09 12:14:41 INFO Received uploads request method=POST path=/api/pending_closures21142026/11/09 12:14:41 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21152026/11/09 12:14:41 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21162026/11/09 12:14:41 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LjEyZTRiMmYyLTdkZmYtNDhmZS1iNmMzLWFlYzFlZDZhMzM3OHgxNzk0MjI2NDgwNjQ2MjcxNzkw parts=1021172026/11/09 12:14:41 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LjI3NWU4YzAzLWY1Y2YtNGZlZC1hYmFhLTczODE3MTcxMDBiYXgxNzk0MjI2NDgwNjE0ODY5NjM3 parts=1021182026/11/09 12:14:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21192026/11/09 12:14:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21202026/11/09 12:14:41 INFO Completed upload id=1 objects=3 duration=2.301991ms21212026/11/09 12:14:41 INFO Received uploads request method=POST path=/api/pending_closures21222026/11/09 12:14:41 INFO Completed upload id=1 objects=3 duration=2.914741ms21232026/11/09 12:14:41 INFO Received uploads request method=POST path=/api/pending_closures21242026/11/09 12:14:41 INFO Received uploads request method=POST path=/api/pending_closures21252026/11/09 12:14:41 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21262026/11/09 12:14:41 WARN Found objects in DB but missing from S3, will re-upload count=121272026/11/09 12:14:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21282026/11/09 12:14:41 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LmJiNWU4MmJiLTk5NzctNDIzMy05NzA5LTViMjNhZWQ2NjY0ZHgxNzk0MjI2NDgwNjU2Mjc5NjM0 parts=1021292026/11/09 12:14:41 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21302026/11/09 12:14:41 INFO Completed upload id=1 objects=3 duration=1.97251ms21312026/11/09 12:14:41 INFO Received uploads request method=POST path=/api/pending_closures21322026/11/09 12:14:41 WARN Request failed, retrying attempt=2 backoff=180.850484ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21332026/11/09 12:14:41 INFO lead: released remote=192.0.2.1:12342134--- PASS: TestUploadHandlersRejectOversizedBody (0.21s)2135 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.04s)2136 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)2137 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.79s)2138--- PASS: TestDeleteClosuresRacingPins (1.77s)21392026/11/09 12:14:41 INFO lead: acquired remote=192.0.2.1:12342140--- PASS: TestPendingClosureWriteTimeout (0.09s)2141 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2142 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2143 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2144 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.04s)21452026/11/09 12:14:41 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21462026/11/09 12:14:41 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21472026/11/09 12:14:41 WARN Request failed, retrying attempt=3 backoff=429.851286ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21482026/11/09 12:14:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21492026/11/09 12:14:41 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LjAyMjVlZjRkLTBiMWItNDNlMy1iOTRjLWRmODVkNGFjZTdjZXgxNzk0MjI2NDgxMTMxMTc1Nzc5 parts=1021502026/11/09 12:14:41 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21512026/11/09 12:14:41 INFO Completed upload id=2 objects=3 duration=801.391µs21522026/11/09 12:14:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21532026/11/09 12:14:41 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=Yzg5Nzg1NWQtZGI4OS00ZmFhLWE3MDgtMjYzYTVhMWQ0ZDk3LjEzNTllYThhLWNhOTMtNDVlZS1hZTcwLWM4M2YzNjU1NDNlN3gxNzk0MjI2NDgxMTYwNjQxODAy parts=1021542026/11/09 12:14:41 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21552026/11/09 12:14:41 INFO Completed upload id=2 objects=3 duration=905.571µs21562026/11/09 12:14:41 INFO Received uploads request method=POST path=/api/pending_closures21572026/11/09 12:14:41 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst21582026/11/09 12:14:41 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo21592026/11/09 12:14:41 INFO Received uploads request method=POST path=/api/pending_closures21602026/11/09 12:14:41 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst21612026/11/09 12:14:41 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2162--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.10s)2163 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (0.78s)2164 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (0.70s)2165 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (0.77s)2166 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (1.10s)2167 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (1.09s)21682026/11/09 12:14:41 WARN Request failed, retrying attempt=4 backoff=729.932055ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2169=== NAME TestOrphanedObjectsGCStressTest2170 orphaned_objects_gc_test.go:503: Stress test completed successfully:2171 orphaned_objects_gc_test.go:504: - Active objects preserved: 202172 orphaned_objects_gc_test.go:505: - Objects deleted: 2102173 orphaned_objects_gc_test.go:506: - Total GC'd: 2102174--- PASS: TestOrphanedObjectsGCStressTest (4.28s)21752026/11/09 12:14:42 INFO lead: released remote=192.0.2.1:12342176--- PASS: TestLeadElectsOneAndHandsOver (3.05s)21772026/11/09 12:14:42 WARN Request failed, retrying attempt=5 backoff=1.610772395s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21782026/11/09 12:14:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021792026/11/09 12:14:42 INFO Received create pin request method=POST path=/api/pins/myapp21802026/11/09 12:14:42 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC1314972430/001/store/yncfvl2phyp1ra22qxv2g12xj018884r-pinned-file.txt narinfo_key=yncfvl2phyp1ra22qxv2g12xj018884r.narinfo21812026/11/09 12:14:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures21822026/11/09 12:14:42 INFO Garbage collection started21832026/11/09 12:14:42 INFO Aborted multipart uploads count=0 kept=021842026/11/09 12:14:42 WARN Force mode enabled - objects will be deleted immediately without grace period21852026/11/09 12:14:42 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021862026/11/09 12:14:42 INFO Vacuumed table table=pending_closures21872026/11/09 12:14:42 INFO Vacuumed table table=pending_objects21882026/11/09 12:14:42 INFO Vacuumed table table=multipart_uploads21892026/11/09 12:14:42 INFO Vacuumed table table=closures21902026/11/09 12:14:42 INFO Vacuumed table table=objects21912026/11/09 12:14:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02192=== NAME TestClientIntegration2193 client_integration_test.go:370: Objects in database after GC:2194 client_integration_test.go:370: Successfully deleted all objects with GC --force2195--- PASS: TestClientIntegration (2.85s)21962026/11/09 12:14:43 WARN Rate limiter enabled after throttle name=s3-test rate=521972026/11/09 12:14:43 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2198=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2199 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102200 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002201--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (5.64s)2202--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.81s)22032026/11/09 12:14:44 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-config22042026/11/09 12:14:44 WARN Request failed, retrying attempt=2 backoff=187.337388ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22052026/11/09 12:14:44 WARN Request failed, retrying attempt=3 backoff=381.018ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2206--- PASS: TestConnectWaitsForAPeerMigration (5.21s)2207=== NAME TestPinProtectsFromGC2208 client_integration_test.go:887: Pin successfully protected closure from garbage collection2209--- PASS: TestPinProtectsFromGC (4.69s)22102026/11/09 12:14:44 INFO Aborted multipart uploads count=1 kept=022112026/11/09 12:14:44 INFO Received cleanup request method=DELETE path=/api/pending_closures22122026/11/09 12:14:44 INFO Aborted multipart uploads count=1 kept=02213--- PASS: TestPendingCleanupUsesOneCutoff (6.56s)22142026/11/09 12:14:44 WARN Request failed, retrying attempt=4 backoff=787.313186ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22152026/11/09 12:14:45 WARN Request failed, retrying attempt=5 backoff=1.580233579s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22162026/11/09 12:14:47 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"22172026/11/09 12:14:47 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-config22182026/11/09 12:14:47 WARN Request failed, retrying attempt=2 backoff=184.371199ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22192026/11/09 12:14:47 WARN Request failed, retrying attempt=3 backoff=407.286578ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22202026/11/09 12:14:47 WARN Request failed, retrying attempt=4 backoff=753.705986ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22212026/11/09 12:14:48 WARN Request failed, retrying attempt=5 backoff=1.75741924s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22222026/11/09 12:14:50 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_closures22232026/11/09 12:14:50 WARN Request failed, retrying attempt=2 backoff=185.553915ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22242026/11/09 12:14:50 WARN Request failed, retrying attempt=3 backoff=423.75525ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22252026/11/09 12:14:51 WARN Request failed, retrying attempt=4 backoff=742.006502ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22262026/11/09 12:14:51 WARN Request failed, retrying attempt=5 backoff=1.702286643s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2227--- PASS: TestClientErrorHandling (0.00s)2228 --- PASS: TestClientErrorHandling/InvalidStorePath (0.22s)2229 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.31s)2230 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.62s)2231PASS2232{"timestamp":"2026-11-09T12:14:53.604727155Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56322","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(386)"}2233{"timestamp":"2026-11-09T12:14:53.604973965Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56456","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(388)"}2234{"timestamp":"2026-11-09T12:14:53.605008995Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55134","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(390)"}22352026-11-09 12:14:53.915 UTC [130] LOG: received smart shutdown request22362026-11-09 12:14:53.921 UTC [130] LOG: background worker "logical replication launcher" (PID 140) exited with exit code 122372026-11-09 12:14:53.935 UTC [135] LOG: shutting down22382026-11-09 12:14:53.936 UTC [135] LOG: checkpoint starting: shutdown immediate22392026-11-09 12:14:54.642 UTC [135] LOG: checkpoint complete: wrote 10875 buffers (66.4%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.304 s, sync=0.351 s, total=0.708 s; sync files=36061, longest=0.020 s, average=0.001 s; distance=521444 kB, estimate=521444 kB; lsn=0/2149F050, redo lsn=0/2149F05022402026-11-09 12:14:54.730 UTC [130] LOG: database system is shut down2241Running OIDC tests...2242=== RUN TestAudienceForIssuer2243=== PAUSE TestAudienceForIssuer2244=== RUN TestGlobMatch2245=== PAUSE TestGlobMatch2246=== RUN TestValidateToken_ValidToken2247=== PAUSE TestValidateToken_ValidToken2248=== RUN TestValidateToken_WrongAudience2249=== PAUSE TestValidateToken_WrongAudience2250=== RUN TestValidateToken_Expired2251=== PAUSE TestValidateToken_Expired2252=== RUN TestValidateToken_BoundClaimsMismatch2253=== PAUSE TestValidateToken_BoundClaimsMismatch2254=== RUN TestValidateToken_BoundSubjectMismatch2255=== PAUSE TestValidateToken_BoundSubjectMismatch2256=== RUN TestValidateToken_MultipleProviders2257=== PAUSE TestValidateToken_MultipleProviders2258=== RUN TestValidateToken_NoMatchingProvider2259=== PAUSE TestValidateToken_NoMatchingProvider2260=== RUN TestValidateToken_KubernetesServiceAccount2261=== PAUSE TestValidateToken_KubernetesServiceAccount2262=== RUN TestNewValidator_KubernetesRequiresCA2263=== PAUSE TestNewValidator_KubernetesRequiresCA2264=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2265=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2266=== RUN TestPins_ReservedForMatchingRule2267=== PAUSE TestPins_ReservedForMatchingRule2268=== RUN TestPins_TopLevelShorthand2269=== PAUSE TestPins_TopLevelShorthand2270=== RUN TestPins_ConfigValidation2271=== PAUSE TestPins_ConfigValidation2272=== RUN TestScopes_LegacyProviderDefaultsToWrite2273=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2274=== RUN TestScopes_Rules2275=== PAUSE TestScopes_Rules2276=== RUN TestScopes_ConfigValidation2277=== PAUSE TestScopes_ConfigValidation2278=== CONT TestAudienceForIssuer2279=== CONT TestScopes_ConfigValidation2280--- PASS: TestAudienceForIssuer (0.00s)2281=== CONT TestValidateToken_NoMatchingProvider2282=== CONT TestValidateToken_MultipleProviders2283=== CONT TestValidateToken_BoundSubjectMismatch2284=== CONT TestValidateToken_BoundClaimsMismatch2285--- PASS: TestScopes_ConfigValidation (0.00s)2286=== CONT TestValidateToken_Expired2287=== CONT TestValidateToken_WrongAudience2288=== CONT TestValidateToken_KubernetesServiceAccount2289=== CONT TestValidateToken_ValidToken2290=== CONT TestPins_ReservedForMatchingRule2291=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2292=== CONT TestGlobMatch2293=== RUN TestGlobMatch/foo_foo2294=== PAUSE TestGlobMatch/foo_foo2295=== CONT TestScopes_LegacyProviderDefaultsToWrite2296=== CONT TestNewValidator_KubernetesRequiresCA2297=== CONT TestScopes_Rules2298=== CONT TestPins_ConfigValidation2299=== CONT TestPins_TopLevelShorthand2300=== RUN TestGlobMatch/foo_bar2301=== PAUSE TestGlobMatch/foo_bar2302=== RUN TestGlobMatch/*_2303=== PAUSE TestGlobMatch/*_2304=== RUN TestGlobMatch/*_anything2305=== PAUSE TestGlobMatch/*_anything2306=== RUN TestGlobMatch/foo*_foo2307=== PAUSE TestGlobMatch/foo*_foo2308=== RUN TestGlobMatch/foo*_foobar2309=== PAUSE TestGlobMatch/foo*_foobar2310=== RUN TestGlobMatch/foo*_bar2311=== PAUSE TestGlobMatch/foo*_bar2312=== RUN TestGlobMatch/*bar_bar2313=== PAUSE TestGlobMatch/*bar_bar2314=== RUN TestGlobMatch/*bar_foobar2315=== PAUSE TestGlobMatch/*bar_foobar2316=== RUN TestGlobMatch/*bar_foo2317=== PAUSE TestGlobMatch/*bar_foo2318=== RUN TestGlobMatch/foo*bar_foobar2319=== PAUSE TestGlobMatch/foo*bar_foobar2320=== RUN TestGlobMatch/foo*bar_foo123bar2321=== PAUSE TestGlobMatch/foo*bar_foo123bar2322=== RUN TestGlobMatch/foo*bar_foobarbaz2323=== PAUSE TestGlobMatch/foo*bar_foobarbaz2324=== RUN TestGlobMatch/*/*_foo/bar2325=== PAUSE TestGlobMatch/*/*_foo/bar2326=== RUN TestGlobMatch/*/*_foo2327=== PAUSE TestGlobMatch/*/*_foo2328=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2329=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2330=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02331=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02332=== RUN TestGlobMatch/refs/*/main_refs/heads/main2333=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2334=== RUN TestGlobMatch/fo?_foo2335=== PAUSE TestGlobMatch/fo?_foo2336=== RUN TestGlobMatch/fo?_fo2337=== PAUSE TestGlobMatch/fo?_fo2338=== RUN TestGlobMatch/fo?_fooo2339=== PAUSE TestGlobMatch/fo?_fooo2340=== RUN TestGlobMatch/?oo_foo2341=== PAUSE TestGlobMatch/?oo_foo2342=== RUN TestGlobMatch/?oo_boo2343=== PAUSE TestGlobMatch/?oo_boo2344=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2345=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2346=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2347=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2348=== CONT TestGlobMatch/foo_foo2349=== CONT TestGlobMatch/foo*bar_foobarbaz2350=== CONT TestGlobMatch/foo*bar_foo123bar2351=== CONT TestGlobMatch/foo*bar_foobar2352=== CONT TestGlobMatch/*bar_foo2353=== CONT TestGlobMatch/*bar_foobar2354=== CONT TestGlobMatch/*bar_bar2355=== CONT TestGlobMatch/foo*_bar2356=== CONT TestGlobMatch/foo*_foobar2357=== CONT TestGlobMatch/foo*_foo2358=== CONT TestGlobMatch/*_anything2359=== CONT TestGlobMatch/*_2360=== CONT TestGlobMatch/foo_bar2361=== CONT TestGlobMatch/fo?_fo2362=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2363=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2364=== CONT TestGlobMatch/refs/*/main_refs/heads/main2365=== CONT TestGlobMatch/*/*_foo/bar2366=== CONT TestGlobMatch/fo?_foo2367=== CONT TestGlobMatch/?oo_boo2368=== CONT TestGlobMatch/?oo_foo2369=== CONT TestGlobMatch/fo?_fooo2370=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2371=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02372=== CONT TestGlobMatch/*/*_foo2373--- PASS: TestGlobMatch (0.00s)2374 --- PASS: TestGlobMatch/foo_foo (0.00s)2375 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2376 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2377 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2378 --- PASS: TestGlobMatch/*bar_foo (0.00s)2379 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2380 --- PASS: TestGlobMatch/*bar_bar (0.00s)2381 --- PASS: TestGlobMatch/foo*_bar (0.00s)2382 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2383 --- PASS: TestGlobMatch/foo*_foo (0.00s)2384 --- PASS: TestGlobMatch/*_anything (0.00s)2385 --- PASS: TestGlobMatch/*_ (0.00s)2386 --- PASS: TestGlobMatch/foo_bar (0.00s)2387 --- PASS: TestGlobMatch/fo?_fo (0.00s)2388 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2389 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2390 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2391 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2392 --- PASS: TestGlobMatch/fo?_foo (0.00s)2393 --- PASS: TestGlobMatch/?oo_boo (0.00s)2394 --- PASS: TestGlobMatch/?oo_foo (0.00s)2395 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2396 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2397 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2398 --- PASS: TestGlobMatch/*/*_foo (0.00s)2399--- PASS: TestPins_ConfigValidation (0.00s)24002026/11/09 12:14:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:33587/oidc24012026/11/09 12:14:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45181/oidc2402--- PASS: TestPins_TopLevelShorthand (0.03s)2403--- PASS: TestPins_ReservedForMatchingRule (0.04s)24042026/11/09 12:14:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45473/oidc2405--- PASS: TestValidateToken_Expired (0.04s)24062026/11/09 12:14:57 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:419332407--- PASS: TestValidateToken_KubernetesServiceAccount (0.07s)24082026/11/09 12:14:57 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232409--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.08s)24102026/11/09 12:14:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45017/oidc24112026/11/09 12:14:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45299/oidc2412--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.08s)2413--- PASS: TestScopes_Rules (0.09s)24142026/11/09 12:14:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:34365/oidc2415--- PASS: TestValidateToken_BoundSubjectMismatch (0.10s)24162026/11/09 12:14:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:36623/oidc24172026/11/09 12:14:57 http: TLS handshake error from 127.0.0.1:57194: remote error: tls: bad certificate2418--- PASS: TestNewValidator_KubernetesRequiresCA (0.13s)2419--- PASS: TestValidateToken_BoundClaimsMismatch (0.14s)24202026/11/09 12:14:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41461/oidc2421--- PASS: TestValidateToken_WrongAudience (0.15s)24222026/11/09 12:14:57 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:38013/oidc2423--- PASS: TestValidateToken_NoMatchingProvider (0.17s)24242026/11/09 12:14:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:39501/oidc2425--- PASS: TestValidateToken_ValidToken (0.21s)24262026/11/09 12:14:57 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:39149/oidc24272026/11/09 12:14:57 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:45851/oidc2428--- PASS: TestValidateToken_MultipleProviders (0.27s)2429PASS2430Running hook tests...2431=== RUN TestSendPathsEmpty2432=== PAUSE TestSendPathsEmpty2433=== RUN TestQueueEnqueueAndFetch2434=== PAUSE TestQueueEnqueueAndFetch2435=== RUN TestQueueDeduplication2436=== PAUSE TestQueueDeduplication2437=== RUN TestQueueRemove2438=== PAUSE TestQueueRemove2439=== RUN TestQueueFetchBatchLimit2440=== PAUSE TestQueueFetchBatchLimit2441=== RUN TestQueueRetryMovesToBack2442=== PAUSE TestQueueRetryMovesToBack2443=== RUN TestQueueFetchRemoveLifecycle2444=== PAUSE TestQueueFetchRemoveLifecycle2445=== RUN TestQueueConcurrentWriters2446=== PAUSE TestQueueConcurrentWriters2447=== RUN TestQueueRemoveLargeClosure2448=== PAUSE TestQueueRemoveLargeClosure2449=== RUN TestServerClientIntegration2450--- PASS: TestServerClientIntegration (0.00s)2451=== RUN TestServerQueueError24522026/11/09 12:14:57 ERROR Failed to queue paths error="permission denied" count=12453--- PASS: TestServerQueueError (0.00s)2454=== RUN TestGetListenerSocketActivation2455 server_test.go:218: === RUN TestGetListenerSocketActivation2456 --- PASS: TestGetListenerSocketActivation (0.00s)2457 PASS2458 2459--- PASS: TestGetListenerSocketActivation (0.01s)2460=== RUN TestServerStalledClientDoesNotBlockShutdown2461=== PAUSE TestServerStalledClientDoesNotBlockShutdown2462=== RUN TestServerBacksOffOnAcceptErrors2463=== PAUSE TestServerBacksOffOnAcceptErrors2464=== RUN TestDrainIsolatesPoisonPath2465=== PAUSE TestDrainIsolatesPoisonPath2466=== RUN TestRunNotBlockedByPoisonHead2467=== PAUSE TestRunNotBlockedByPoisonHead2468=== RUN TestDrainGivesUpWhenServerDown2469=== PAUSE TestDrainGivesUpWhenServerDown2470=== RUN TestFailedPathPrunedByLaterClosure2471=== PAUSE TestFailedPathPrunedByLaterClosure2472=== RUN TestWorkerUploadsAndRemoves2473=== PAUSE TestWorkerUploadsAndRemoves2474=== RUN TestWorkerSkipsGCdPaths2475=== PAUSE TestWorkerSkipsGCdPaths2476=== RUN TestWorkerPrunesClosureDeps2477=== PAUSE TestWorkerPrunesClosureDeps2478=== RUN TestDrainTimeout2479=== PAUSE TestDrainTimeout2480=== RUN TestWorkerRemoveFailureIsNotProgress2481=== PAUSE TestWorkerRemoveFailureIsNotProgress2482=== RUN TestWorkerKeepsPathItCannotStat2483=== PAUSE TestWorkerKeepsPathItCannotStat2484=== CONT TestSendPathsEmpty2485=== CONT TestDrainIsolatesPoisonPath2486--- PASS: TestSendPathsEmpty (0.00s)2487=== CONT TestQueueRetryMovesToBack2488=== CONT TestQueueFetchBatchLimit2489=== CONT TestQueueRemove2490=== CONT TestQueueDeduplication2491=== CONT TestQueueFetchRemoveLifecycle2492=== CONT TestQueueEnqueueAndFetch2493=== CONT TestServerBacksOffOnAcceptErrors2494=== CONT TestWorkerSkipsGCdPaths24952026/11/09 12:14:57 ERROR Accept failed error="too many open files"2496=== CONT TestServerStalledClientDoesNotBlockShutdown2497=== CONT TestWorkerKeepsPathItCannotStat2498=== CONT TestQueueRemoveLargeClosure2499=== CONT TestWorkerRemoveFailureIsNotProgress2500=== CONT TestDrainTimeout2501=== CONT TestQueueConcurrentWriters2502=== CONT TestWorkerPrunesClosureDeps2503=== CONT TestWorkerUploadsAndRemoves2504=== CONT TestDrainGivesUpWhenServerDown2505=== CONT TestFailedPathPrunedByLaterClosure2506=== CONT TestRunNotBlockedByPoisonHead25072026/11/09 12:14:57 ERROR Accept failed error="too many open files"25082026/11/09 12:14:57 INFO Uploading batch count=425092026/11/09 12:14:57 ERROR Upload failed error="upload failed" count=425102026/11/09 12:14:57 INFO Uploading batch count=125112026/11/09 12:14:57 ERROR Upload failed error="upload failed" count=125122026/11/09 12:14:57 INFO Upload queue status pending=225132026/11/09 12:14:57 INFO Uploading batch count=225142026/11/09 12:14:57 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath3035441754/002/bbb25152026/11/09 12:14:57 INFO Uploading batch count=225162026/11/09 12:14:57 ERROR Upload failed error="upload failed" count=225172026/11/09 12:14:57 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown305551779/002/a25182026/11/09 12:14:57 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat3701073543/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat3701073543/002/locked/aaa: permission denied"25192026/11/09 12:14:57 INFO Upload queue status pending=225202026/11/09 12:14:57 INFO Uploading batch count=225212026/11/09 12:14:57 INFO Upload queue status pending=225222026/11/09 12:14:57 INFO Uploading batch count=125232026/11/09 12:14:57 ERROR Accept failed error="too many open files"25242026/11/09 12:14:57 INFO Uploading batch count=12525--- PASS: TestQueueFetchBatchLimit (0.02s)25262026/11/09 12:14:57 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths1278340479/002/nonexistent25272026/11/09 12:14:57 INFO Upload queue status pending=325282026/11/09 12:14:57 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat3701073543/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat3701073543/002/locked/aaa: permission denied"2529--- PASS: TestQueueRemove (0.02s)25302026/11/09 12:14:57 INFO Uploading batch count=12531--- PASS: TestQueueRetryMovesToBack (0.02s)25322026/11/09 12:14:57 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown305551779/002/b2533--- PASS: TestQueueDeduplication (0.02s)25342026/11/09 12:14:57 INFO Uploading batch count=125352026/11/09 12:14:57 ERROR Upload failed error="upload failed" count=125362026/11/09 12:14:57 INFO Uploading batch count=125372026/11/09 12:14:57 INFO Uploading batch count=125382026/11/09 12:14:57 ERROR Upload failed error="upload failed" count=125392026/11/09 12:14:57 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1069099525/002/nonexistent2540--- PASS: TestQueueEnqueueAndFetch (0.02s)25412026/11/09 12:14:57 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat3701073543/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat3701073543/002/locked/aaa: permission denied"25422026/11/09 12:14:57 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125432026/11/09 12:14:57 INFO Uploading batch count=22544--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25452026/11/09 12:14:57 ERROR Upload failed error="upload failed" count=225462026/11/09 12:14:57 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown305551779/002/c25472026/11/09 12:14:57 INFO Uploading batch count=125482026/11/09 12:14:57 ERROR Upload failed error="upload failed" count=125492026/11/09 12:14:57 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1069099525/002/nonexistent25502026/11/09 12:14:57 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125512026/11/09 12:14:57 ERROR Drain finished with paths left in queue remaining=125522026/11/09 12:14:57 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress1069099525/002/nonexistent25532026/11/09 12:14:57 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125542026/11/09 12:14:57 ERROR Drain finished with paths left in queue remaining=125552026/11/09 12:14:57 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown305551779/002/d25562026/11/09 12:14:57 INFO Uploading batch count=125572026/11/09 12:14:57 ERROR Upload failed error="upload failed" count=12558--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25592026/11/09 12:14:57 INFO Uploading batch count=225602026/11/09 12:14:57 ERROR Upload failed error="upload failed" count=225612026/11/09 12:14:57 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown305551779/002/e25622026/11/09 12:14:57 ERROR Drain finished with paths left in queue remaining=12563--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)25642026/11/09 12:14:57 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown305551779/002/f2565--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)25662026/11/09 12:14:57 ERROR Drain finished with paths left in queue remaining=102567--- PASS: TestDrainIsolatesPoisonPath (0.03s)2568--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2569--- PASS: TestWorkerUploadsAndRemoves (0.03s)2570--- PASS: TestWorkerPrunesClosureDeps (0.03s)25712026/11/09 12:14:57 ERROR Accept failed error="too many open files"2572--- PASS: TestWorkerSkipsGCdPaths (0.04s)2573--- PASS: TestQueueRemoveLargeClosure (0.05s)25742026/11/09 12:14:57 ERROR Accept failed error="too many open files"2575--- PASS: TestQueueConcurrentWriters (0.15s)25762026/11/09 12:14:57 ERROR Accept failed error="too many open files"25772026/11/09 12:14:57 ERROR Failed to decode request error="read unix /build/hook2917135561/test.sock->@: i/o timeout"25782026/11/09 12:14:57 ERROR Failed to write response error="write unix /build/hook2917135561/test.sock->@: i/o timeout"2579--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)25802026/11/09 12:14:57 ERROR Upload failed error="context deadline exceeded" count=225812026/11/09 12:14:57 ERROR Drain finished with paths left in queue remaining=42582--- PASS: TestDrainTimeout (0.22s)25832026/11/09 12:14:57 ERROR Accept failed error="too many open files"25842026/11/09 12:14:58 ERROR Accept failed error="too many open files"2585--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)25862026/11/09 12:14:58 INFO Uploading batch count=125872026/11/09 12:14:58 INFO Uploading batch count=125882026/11/09 12:14:58 INFO Uploading batch count=125892026/11/09 12:14:58 ERROR Upload failed error="upload failed" count=125902026/11/09 12:14:58 INFO Uploading batch count=125912026/11/09 12:14:58 ERROR Upload failed error="upload failed" count=125922026/11/09 12:14:58 INFO Uploading batch count=125932026/11/09 12:14:58 ERROR Upload failed error="upload failed" count=125942026/11/09 12:14:58 INFO Uploading batch count=125952026/11/09 12:14:58 ERROR Upload failed error="upload failed" count=125962026/11/09 12:14:58 ERROR Drain finished with paths left in queue remaining=12597--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2598PASS2599Running signing tests...2600=== RUN TestExternalSigner2601=== PAUSE TestExternalSigner2602=== RUN TestExternalSignerWrongPublicKey2603=== PAUSE TestExternalSignerWrongPublicKey2604=== RUN TestExternalSignerErrors2605=== PAUSE TestExternalSignerErrors2606=== RUN TestExternalSignerRestartsAfterCrash2607=== PAUSE TestExternalSignerRestartsAfterCrash2608=== RUN TestExternalSignerProgramErrorKeepsProcess2609=== PAUSE TestExternalSignerProgramErrorKeepsProcess2610=== RUN TestExternalSignerClose2611=== PAUSE TestExternalSignerClose2612=== RUN TestExternalSignerRejectsInvalidPublicKey2613=== PAUSE TestExternalSignerRejectsInvalidPublicKey2614=== RUN TestExternalSignerCancellation2615=== PAUSE TestExternalSignerCancellation2616=== RUN TestGenerateFingerprint2617=== PAUSE TestGenerateFingerprint2618=== RUN TestParseSigningKey2619=== PAUSE TestParseSigningKey2620=== RUN TestSign2621=== PAUSE TestSign2622=== RUN TestSignBatch2623=== PAUSE TestSignBatch2624=== RUN TestNilKeyPublicKey2625=== PAUSE TestNilKeyPublicKey2626=== RUN TestSignErrors2627=== PAUSE TestSignErrors2628=== CONT TestExternalSigner2629=== CONT TestExternalSignerCancellation2630=== CONT TestSignBatch2631=== CONT TestSignErrors2632=== CONT TestParseSigningKey2633=== CONT TestNilKeyPublicKey2634--- PASS: TestNilKeyPublicKey (0.00s)2635=== CONT TestSign2636=== CONT TestExternalSignerProgramErrorKeepsProcess2637=== CONT TestExternalSignerRejectsInvalidPublicKey2638=== CONT TestExternalSignerClose2639=== CONT TestExternalSignerErrors2640=== CONT TestGenerateFingerprint2641=== CONT TestExternalSignerRestartsAfterCrash2642=== CONT TestExternalSignerWrongPublicKey2643=== RUN TestParseSigningKey/valid_32-byte_key2644=== RUN TestExternalSignerRejectsInvalidPublicKey/#002645=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002646=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2647=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2648=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2649=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2650=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2651=== RUN TestExternalSignerErrors/exit_on_request2652=== PAUSE TestExternalSignerErrors/exit_on_request2653=== RUN TestExternalSignerErrors/wrong_shape2654=== PAUSE TestExternalSignerErrors/wrong_shape2655=== RUN TestExternalSignerErrors/null2656=== PAUSE TestExternalSignerErrors/null2657=== RUN TestExternalSignerErrors/too_few_signatures2658=== RUN TestSignErrors/nil_key2659=== RUN TestGenerateFingerprint/basic_with_references2660=== PAUSE TestGenerateFingerprint/basic_with_references2661=== PAUSE TestParseSigningKey/valid_32-byte_key2662=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2663=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2664=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2665=== RUN TestGenerateFingerprint/no_references2666=== PAUSE TestGenerateFingerprint/no_references2667=== CONT TestExternalSignerRejectsInvalidPublicKey/#002668=== PAUSE TestExternalSignerErrors/too_few_signatures2669=== PAUSE TestSignErrors/nil_key2670=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2671=== RUN TestSignErrors/nil_narinfo2672=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2673=== PAUSE TestSignErrors/nil_narinfo2674=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2675=== RUN TestSignErrors/invalid_narinfo2676=== RUN TestParseSigningKey/no_colon2677=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2678=== PAUSE TestSignErrors/invalid_narinfo2679=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2680=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2681=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2682=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2683=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2684=== RUN TestExternalSignerErrors/program_error2685=== PAUSE TestExternalSignerErrors/program_error2686--- PASS: TestSign (0.00s)2687=== PAUSE TestParseSigningKey/no_colon2688--- PASS: TestSignBatch (0.00s)2689=== RUN TestParseSigningKey/empty_name2690=== PAUSE TestParseSigningKey/empty_name2691--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2692 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2693 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2694 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2695 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2696 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2697=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2698=== RUN TestExternalSignerErrors/exit_at_startup2699=== PAUSE TestExternalSignerErrors/exit_at_startup2700=== RUN TestExternalSignerErrors/invalid_JSON2701=== PAUSE TestExternalSignerErrors/invalid_JSON2702=== RUN TestExternalSignerErrors/wrong_id2703=== PAUSE TestExternalSignerErrors/wrong_id2704=== RUN TestExternalSignerErrors/null_signatures2705=== PAUSE TestExternalSignerErrors/null_signatures2706=== RUN TestSignErrors/canceled2707=== PAUSE TestSignErrors/canceled2708=== CONT TestSignErrors/nil_key2709=== CONT TestSignErrors/invalid_narinfo2710=== RUN TestParseSigningKey/invalid_base642711=== PAUSE TestParseSigningKey/invalid_base642712=== RUN TestParseSigningKey/wrong_length2713=== PAUSE TestParseSigningKey/wrong_length2714=== CONT TestParseSigningKey/valid_32-byte_key2715=== CONT TestParseSigningKey/no_colon2716=== CONT TestSignErrors/canceled2717=== RUN TestGenerateFingerprint/invalid_nar_hash_length2718=== RUN TestExternalSignerErrors/unrequested_key2719=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2720=== CONT TestSignErrors/nil_narinfo2721--- PASS: TestSignErrors (0.00s)2722 --- PASS: TestSignErrors/nil_key (0.00s)2723 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2724 --- PASS: TestSignErrors/canceled (0.00s)2725 --- PASS: TestSignErrors/nil_narinfo (0.00s)2726=== CONT TestParseSigningKey/empty_name2727=== CONT TestParseSigningKey/invalid_base642728=== CONT TestParseSigningKey/wrong_length2729=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2730--- PASS: TestParseSigningKey (0.00s)2731 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2732 --- PASS: TestParseSigningKey/no_colon (0.00s)2733 --- PASS: TestParseSigningKey/empty_name (0.00s)2734 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2735 --- PASS: TestParseSigningKey/wrong_length (0.00s)2736 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2737=== PAUSE TestExternalSignerErrors/unrequested_key2738=== RUN TestExternalSignerErrors/missing_signature_name2739=== PAUSE TestExternalSignerErrors/missing_signature_name2740=== RUN TestGenerateFingerprint/invalid_store_path_prefix2741=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2742=== RUN TestExternalSignerErrors/wrong_signature_length2743=== PAUSE TestExternalSignerErrors/wrong_signature_length2744=== RUN TestGenerateFingerprint/invalid_reference_prefix2745=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2746=== CONT TestGenerateFingerprint/basic_with_references2747=== CONT TestGenerateFingerprint/invalid_nar_hash_length2748--- PASS: TestExternalSignerClose (0.00s)2749--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2750=== CONT TestGenerateFingerprint/invalid_reference_prefix2751=== RUN TestExternalSignerErrors/missing_signatures2752=== PAUSE TestExternalSignerErrors/missing_signatures2753=== RUN TestExternalSignerErrors/invalid_signature_base642754=== PAUSE TestExternalSignerErrors/invalid_signature_base642755=== RUN TestExternalSignerErrors/wrong_signatures_shape2756=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2757=== RUN TestExternalSignerErrors/wrong_signature_name2758=== PAUSE TestExternalSignerErrors/wrong_signature_name2759=== CONT TestExternalSignerErrors/exit_on_request2760=== CONT TestExternalSignerErrors/unrequested_key2761=== CONT TestExternalSignerErrors/null2762=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2763=== CONT TestExternalSignerErrors/program_error2764=== CONT TestExternalSignerErrors/invalid_signature_base642765=== CONT TestGenerateFingerprint/invalid_store_path_prefix2766=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2767=== CONT TestGenerateFingerprint/no_references2768--- PASS: TestGenerateFingerprint (0.00s)2769 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2770 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2771 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2772 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2773 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2774 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2775 --- PASS: TestGenerateFingerprint/no_references (0.00s)2776=== CONT TestExternalSignerErrors/wrong_signature_name2777=== CONT TestExternalSignerErrors/wrong_signatures_shape2778=== CONT TestExternalSignerErrors/wrong_signature_length2779=== CONT TestExternalSignerErrors/exit_at_startup2780=== CONT TestExternalSignerErrors/missing_signatures2781=== CONT TestExternalSignerErrors/null_signatures2782=== CONT TestExternalSignerErrors/wrong_id2783=== CONT TestExternalSignerErrors/missing_signature_name2784=== CONT TestExternalSignerErrors/too_few_signatures2785=== CONT TestExternalSignerErrors/invalid_JSON2786=== CONT TestExternalSignerErrors/wrong_shape2787--- PASS: TestExternalSigner (0.01s)2788--- PASS: TestExternalSignerWrongPublicKey (0.01s)2789--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2790--- PASS: TestExternalSignerErrors (0.00s)2791 --- PASS: TestExternalSignerErrors/exit_on_request (0.00s)2792 --- PASS: TestExternalSignerErrors/unrequested_key (0.00s)2793 --- PASS: TestExternalSignerErrors/null (0.01s)2794 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)2795 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2796 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2797 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.01s)2798 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2799 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2800 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2801 --- PASS: TestExternalSignerErrors/missing_signature_name (0.01s)2802 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2803 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2804 --- PASS: TestExternalSignerErrors/program_error (0.01s)2805 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2806 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2807--- PASS: TestExternalSignerCancellation (0.02s)2808PASS2809Running OpenBao signer tests...2810=== RUN TestSign2811=== PAUSE TestSign2812=== RUN TestSignErrors2813=== PAUSE TestSignErrors2814=== RUN TestServe2815=== PAUSE TestServe2816=== RUN TestServeRejectsGarbage2817=== PAUSE TestServeRejectsGarbage2818=== CONT TestSign2819=== CONT TestServe2820=== CONT TestServeRejectsGarbage2821=== CONT TestSignErrors2822--- PASS: TestServeRejectsGarbage (0.00s)2823=== RUN TestSignErrors/no_prefix2824--- PASS: TestServe (0.00s)2825=== PAUSE TestSignErrors/no_prefix2826=== RUN TestSignErrors/invalid_base642827=== PAUSE TestSignErrors/invalid_base642828=== RUN TestSignErrors/http_error2829=== PAUSE TestSignErrors/http_error2830=== RUN TestSignErrors/invalid_json2831=== PAUSE TestSignErrors/invalid_json2832=== CONT TestSignErrors/no_prefix2833=== CONT TestSignErrors/http_error2834=== CONT TestSignErrors/invalid_base642835=== CONT TestSignErrors/invalid_json2836--- PASS: TestSignErrors (0.00s)2837 --- PASS: TestSignErrors/invalid_base64 (0.00s)2838 --- PASS: TestSignErrors/http_error (0.00s)2839 --- PASS: TestSignErrors/no_prefix (0.00s)2840 --- PASS: TestSignErrors/invalid_json (0.00s)2841--- PASS: TestSign (0.00s)2842PASS