niks3-go-unit-tests
checks.x86_64-linux.go-unit-tests
· build #482
· 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.03s)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 TestStreamPushReportsEveryPath115=== CONT TestPathInfoHashCompatibility116=== CONT TestShellSplitErrors117--- PASS: TestShellSplitErrors (0.00s)118=== CONT TestDoWithRetry_BodyReplayedViaGetBody119=== CONT TestShellSplit120--- PASS: TestShellSplit (0.00s)121=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer122--- PASS: TestStreamPushReportsEveryPath (0.00s)123=== CONT TestFileTokenEmpty124=== CONT TestDoWithRetry_FinalResponseBodyReadable125=== CONT TestRateLimiterFeedback126=== CONT TestSetClientTLSErrors127=== RUN TestRateLimiterFeedback/429_enables_limiter128--- PASS: TestFileTokenEmpty (0.00s)129=== PAUSE TestRateLimiterFeedback/429_enables_limiter130=== RUN TestRateLimiterFeedback/503_enables_limiter131=== CONT TestPathInfoCACompatibility132=== CONT TestParsePathInfoJSONMultiplePaths133=== CONT TestScriptTokenEmptyCommand134=== CONT TestParsePathInfoJSON135=== CONT TestScriptTokenScriptFails136=== CONT TestScriptTokenBadJSON137=== CONT TestScriptTokenEmptyToken138=== CONT TestScriptTokenCachesUntilRefresh139=== CONT TestScriptTokenNoExpiryRerunsEveryCall140=== CONT TestFileTokenReadsAndCaches141=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess142=== CONT TestStaticToken143=== CONT TestRetryTimeoutOutlastsMaxRetries144=== CONT TestResolveStorePath145=== CONT TestRegisterUploadedObject_OutlivesPush146=== CONT TestGetStorePathHash147=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)148=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)149=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths150=== CONT TestStreamPushReportsSkippedPaths151=== PAUSE TestRateLimiterFeedback/503_enables_limiter152=== RUN TestPathInfoCACompatibility/null_ca_field153=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths154=== PAUSE TestPathInfoCACompatibility/null_ca_field1552026/11/11 22:22:31 WARN Rate limiter enabled after throttle name=server-test rate=5156--- PASS: TestScriptTokenEmptyCommand (0.00s)157=== CONT TestStreamPushGivesUpOnDeadServer1582026/11/11 22:22:31 WARN Rate limiter enabled after throttle name=server-test rate=5159=== RUN TestParsePathInfoJSON/Nix_format160=== RUN TestGetStorePathHash/valid_store_path1612026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:444791622026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:36881163=== CONT TestStreamPushRequestLine164=== CONT TestStreamPushReportsSignatures165=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter166=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths167=== RUN TestPathInfoCACompatibility/old_string_format_-_text168=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon169--- PASS: TestScriptTokenScriptFails (0.00s)170=== CONT TestSetClientTLSDoesNotMutateDefaultTransport171--- PASS: TestStaticToken (0.00s)172=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text173=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon174=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths175--- PASS: TestFileTokenReadsAndCaches (0.00s)176--- PASS: TestStreamPushReportsSkippedPaths (0.00s)177=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive178=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive179=== PAUSE TestParsePathInfoJSON/Nix_format180=== RUN TestPathInfoCACompatibility/new_structured_format_-_text181=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text182=== RUN TestParsePathInfoJSON/Lix_format1832026/11/11 22:22:31 WARN Rate limiter backed off name=server-test rate=51842026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:444791852026/11/11 22:22:31 ERROR Upload failed error="connection refused" count=20186=== PAUSE TestGetStorePathHash/valid_store_path1872026/11/11 22:22:31 ERROR Server seems unavailable, giving up on batch untried=17188=== RUN TestGetStorePathHash/basename_without_hyphen_should_error1892026/11/11 22:22:31 ERROR Upload failed error=boom count=1190=== CONT TestSetClientTLS1912026/11/11 22:22:31 ERROR Upload failed error=boom count=1192=== CONT TestStreamPushStopsWhenCanceled193=== CONT TestDumpPathWriterError194=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter1952026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:36881196=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter1972026/11/11 22:22:31 WARN Rate limiter enabled after throttle name=server-test rate=5198=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI199=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI200=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method2012026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:46095202--- PASS: TestScriptTokenEmptyToken (0.01s)203--- PASS: TestResolveStorePath (0.00s)204--- PASS: TestDoServerRequestAttachesToken (0.01s)205=== CONT TestUploadMultipart_ReturnsAfterDroppedBody206--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)207--- PASS: TestStreamPushReportsSignatures (0.00s)208--- PASS: TestStreamPushStopsWhenCanceled (0.00s)209=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error210=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512211=== CONT TestStreamPushIsolatesFailures212=== PAUSE TestParsePathInfoJSON/Lix_format213=== CONT TestClientSignaturesByStorePath214=== CONT TestConvertHashToNix32215=== CONT TestDumpPathSingleFile216=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter217=== CONT TestEncodeNixBase32WithRealHash218=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method219=== CONT TestEncodeNixBase32220=== CONT TestPartSizeForNAR221=== RUN TestEncodeNixBase32/test_string_hash222--- PASS: TestRegisterUploadedObject_OutlivesPush (0.01s)223=== CONT TestDumpPathMatchesNix224--- PASS: TestScriptTokenBadJSON (0.01s)225=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512226=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error227=== CONT TestStreamPushBatchesUnderLoad228=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error229=== RUN TestParsePathInfoJSON/empty_input230=== PAUSE TestParsePathInfoJSON/empty_input231=== RUN TestParsePathInfoJSON/whitespace_only232=== PAUSE TestParsePathInfoJSON/whitespace_only233=== RUN TestParsePathInfoJSON/invalid_JSON234=== PAUSE TestEncodeNixBase32/test_string_hash2352026/11/11 22:22:31 ERROR Upload failed error="bad path" count=3236=== CONT TestFilterOversizedClosures2372026/11/11 22:22:31 WARN Rate limiter backed off name=server-test rate=5238=== RUN TestFilterOversizedClosures/no_limit_keeps_everything239=== RUN TestConvertHashToNix32/SRI_format_to_Nix32240=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error241=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error242=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun243=== PAUSE TestParsePathInfoJSON/invalid_JSON244=== RUN TestSetClientTLSErrors/missing_cert_file245=== CONT TestCaseHackSuffix246--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)247=== RUN TestPartSizeForNAR/zero_stays_at_minimum248=== RUN TestEncodeNixBase32/empty_input249=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything250=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32251--- PASS: TestEncodeNixBase32WithRealHash (0.00s)252--- PASS: TestClientSignaturesByStorePath (0.00s)253=== CONT TestUploadMultipart_PartsInParallel2542026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:36881255=== CONT TestFileTokenMissing256=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false257=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false258=== CONT TestRegisterUploadedObjectReusesConnections259=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry260=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica261=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum262=== PAUSE TestEncodeNixBase32/empty_input263=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths2642026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:36881265=== RUN TestPartSizeForNAR/small_stays_at_minimum266=== PAUSE TestPartSizeForNAR/small_stays_at_minimum267=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum268=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum269=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts270=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts271=== RUN TestPartSizeForNAR/1_TiB272=== PAUSE TestPartSizeForNAR/1_TiB273=== RUN TestPartSizeForNAR/5_TiB_S3_max_object2742026/11/11 22:22:31 INFO Garbage collection started275=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object276=== RUN TestPartSizeForNAR/capped_at_5_GiB277=== PAUSE TestPartSizeForNAR/capped_at_5_GiB278=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method279=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter2802026/11/11 22:22:31 INFO Garbage collection started281=== CONT TestPathInfoCACompatibility/null_ca_field282=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter283=== CONT TestRateLimiterFeedback/503_enables_limiter284=== CONT TestPathInfoCACompatibility/old_string_format_-_text285=== CONT TestPathInfoCACompatibility/new_structured_format_-_text286=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped287=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped288=== RUN TestFilterOversizedClosures/all_closures_skipped289=== PAUSE TestFilterOversizedClosures/all_closures_skipped290=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive291=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512292=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)293=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon294=== CONT TestParsePathInfoJSON/Nix_format295=== CONT TestParsePathInfoJSON/invalid_JSON296=== CONT TestParsePathInfoJSON/whitespace_only297=== CONT TestParsePathInfoJSON/empty_input298=== CONT TestParsePathInfoJSON/Lix_format299--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)300--- PASS: TestStreamPushIsolatesFailures (0.00s)301--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.00s)302--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)303=== CONT TestGetStorePathHash/valid_store_path304=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error305=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error306=== CONT TestEncodeNixBase32/empty_input307=== CONT TestPartSizeForNAR/capped_at_5_GiB308=== CONT TestEncodeNixBase32/test_string_hash309=== CONT TestPartSizeForNAR/1_TiB310=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts311=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum312=== CONT TestPartSizeForNAR/small_stays_at_minimum313=== CONT TestFilterOversizedClosures/no_limit_keeps_everything314=== CONT TestFilterOversizedClosures/all_closures_skipped3152026/11/11 22:22:31 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50316=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3172026/11/11 22:22:31 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=2000318=== CONT TestPartSizeForNAR/5_TiB_S3_max_object319=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI320=== CONT TestPartSizeForNAR/zero_stays_at_minimum3212026/11/11 22:22:31 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=0322=== CONT TestGetStorePathHash/basename_without_hyphen_should_error3232026/11/11 22:22:31 WARN Rate limiter enabled after throttle name=server-test rate=5324=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths3252026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:39839326=== RUN TestSetClientTLS/rejects_connection_without_client_cert3272026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:36881328=== RUN TestConvertHashToNix32/already_Nix32_format3292026/11/11 22:22:31 WARN Rate limiter backed off name=server-test rate=5330=== PAUSE TestConvertHashToNix32/already_Nix32_format331=== CONT TestRateLimiterFeedback/429_enables_limiter332--- PASS: TestFileTokenMissing (0.00s)333=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true334=== PAUSE TestSetClientTLSErrors/missing_cert_file335=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert336=== RUN TestConvertHashToNix32/invalid_format3372026/11/11 22:22:31 WARN Rate limiter enabled after throttle name=server-test rate=5338--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.06s)3392026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:43133340=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true3412026/11/11 22:22:31 WARN Rate limiter enabled after throttle name=s3-test rate=5342=== RUN TestSetClientTLSErrors/missing_key_file3432026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:46123344=== PAUSE TestSetClientTLSErrors/missing_key_file3452026/11/11 22:22:31 WARN Garbage collection finished on another replica. Its statistics are not available here346=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA3472026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:36881348=== PAUSE TestConvertHashToNix32/invalid_format3492026/11/11 22:22:31 WARN Rate limiter backed off name=server-test rate=5350--- PASS: TestScriptTokenCachesUntilRefresh (0.07s)351=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false352=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true353=== RUN TestSetClientTLSErrors/missing_ca_file354=== PAUSE TestSetClientTLSErrors/missing_ca_file355=== RUN TestSetClientTLSErrors/invalid_ca_file356=== PAUSE TestSetClientTLSErrors/invalid_ca_file357=== CONT TestSetClientTLSErrors/missing_cert_file358=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA359=== RUN TestSetClientTLS/preserves_debug_logging_transport360=== PAUSE TestSetClientTLS/preserves_debug_logging_transport361=== CONT TestSetClientTLSErrors/invalid_ca_file362=== CONT TestConvertHashToNix32/SRI_format_to_Nix32363=== CONT TestConvertHashToNix32/invalid_format364=== CONT TestConvertHashToNix32/already_Nix32_format3652026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:36881366--- PASS: TestPathInfoCACompatibility (0.01s)367 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)368 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)369 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)370 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)371 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)372=== CONT TestSetClientTLSErrors/missing_key_file373=== CONT TestSetClientTLSErrors/missing_ca_file374=== CONT TestSetClientTLS/rejects_connection_without_client_cert375=== CONT TestSetClientTLS/preserves_debug_logging_transport376=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA377--- PASS: TestDumpPathSingleFile (0.06s)3782026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:36881379--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.06s)380--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.06s)381--- PASS: TestPathInfoHashCompatibility (0.01s)382 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)383 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)384 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)385 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)386--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.06s)387--- PASS: TestStreamPushBatchesUnderLoad (0.06s)388 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)389 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)390--- PASS: TestConvertHashToNix32 (0.06s)391 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)392 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)393 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)394--- PASS: TestEncodeNixBase32 (0.06s)395 --- PASS: TestEncodeNixBase32/empty_input (0.00s)396 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)397--- PASS: TestParsePathInfoJSON (0.01s)398 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)399 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)400 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)401 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)402 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)403--- PASS: TestFilterOversizedClosures (0.06s)404 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)405 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)406 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)407--- PASS: TestPartSizeForNAR (0.06s)408 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)409 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)410 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)411 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)412 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)413 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)414 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)415--- PASS: TestRateLimiterFeedback (0.01s)416 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)417 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)418 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)419 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)420--- PASS: TestGetStorePathHash (0.01s)421 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)422 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)423 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)424 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)425--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)426 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)427 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)4282026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:36881429--- PASS: TestSetClientTLSErrors (0.07s)430 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)431 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)432 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)433 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)4342026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:368814352026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:368814362026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:368814372026/11/11 22:22:31 http: TLS handshake error from 127.0.0.1:40204: remote error: tls: bad certificate4382026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:36881439--- PASS: TestSetClientTLS (0.08s)440 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.00s)441 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.00s)442 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.01s)4432026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:368814442026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:368814452026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:36881446--- PASS: TestStreamPushRequestLine (0.09s)447--- PASS: TestCaseHackSuffix (0.08s)4482026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:368814492026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:368814502026/11/11 22:22:31 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:368814512026/11/11 22:22:31 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:46691/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:46691/api/uploads/complete4522026/11/11 22:22:31 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4532026/11/11 22:22:31 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:46691/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:46691/api/uploads/complete4542026/11/11 22:22:31 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4552026/11/11 22:22:31 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:46691/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:46691/api/uploads/complete4562026/11/11 22:22:31 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"457--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.10s)458--- PASS: TestRegisterUploadedObjectReusesConnections (0.09s)459--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.10s)460--- PASS: TestDumpPathWriterError (0.11s)461--- PASS: TestDumpPathMatchesNix (0.16s)462--- PASS: TestUploadMultipart_PartsInParallel (0.68s)463--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)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/postgres1468783690/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/postgres1468783690/data -l logfile start492493/build/postgres1468783690:5432 - no response4942026-11-11 22:22:33.471 UTC [129] LOG: starting PostgreSQL 18.6 on x86_64-pc-linux-gnu, compiled by clang version 21.1.8, 64-bit4952026-11-11 22:22:33.471 UTC [129] LOG: listening on Unix socket "/build/postgres1468783690/.s.PGSQL.5432"4962026-11-11 22:22:33.476 UTC [136] LOG: database system was shut down at 2026-11-11 22:22:33 UTC4972026-11-11 22:22:33.480 UTC [129] LOG: database system is ready to accept connections498/build/postgres1468783690: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/11 22:22:34 INFO lead: acquired remote=192.0.2.1:1234 generation=15492026/11/11 22:22:34 INFO lead: released remote=192.0.2.1:1234 generation=15502026/11/11 22:22:34 INFO lead: acquired remote=192.0.2.1:1234 generation=25512026/11/11 22:22:35 INFO lead: released remote=192.0.2.1:1234 generation=2552--- PASS: TestLeadIncumbentWinsAfterRestart (1.89s)553=== RUN TestLeadUnannouncedStandbyYieldsToIncumbent554=== PAUSE TestLeadUnannouncedStandbyYieldsToIncumbent555=== RUN TestLeadIncumbentAnnouncesAtOnce556=== PAUSE TestLeadIncumbentAnnouncesAtOnce557=== RUN TestLeadGenerationGrowsWithEveryGrant558=== PAUSE TestLeadGenerationGrowsWithEveryGrant559=== RUN TestLeadEndsOnShutdown560=== PAUSE TestLeadEndsOnShutdown561=== RUN TestLeadEndsWhenItsConnectionHangs5622026/11/11 22:22:35 INFO lead: acquired remote=192.0.2.1:1234 generation=15632026-11-11 22:22:37.300 UTC [578] FATAL: terminating connection due to administrator command5642026/11/11 22:22:37 INFO lead: acquired remote=192.0.2.1:1234 generation=25652026/11/11 22:22:38 WARN lead: lock connection lost error="timeout: context deadline exceeded"5662026/11/11 22:22:38 INFO lead: released remote=192.0.2.1:1234 generation=15672026/11/11 22:22:38 INFO lead: released remote=192.0.2.1:1234 generation=2568--- PASS: TestLeadEndsWhenItsConnectionHangs (2.93s)569=== RUN TestGCAdvisoryLockBlocksConcurrentRun570=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun571=== RUN TestGCBugBareHashReferences572=== PAUSE TestGCBugBareHashReferences573=== RUN TestGCMetrics574=== PAUSE TestGCMetrics575=== RUN TestPushDedupSurvivesConcurrentGC576=== PAUSE TestPushDedupSurvivesConcurrentGC577=== RUN TestDeduplicatedObjectsRecordedAsPending578=== PAUSE TestDeduplicatedObjectsRecordedAsPending579=== RUN TestGCSweepSkipsPendingObjects580=== PAUSE TestGCSweepSkipsPendingObjects581=== RUN TestTombstonedObjectOfferedWithoutWaiting582=== PAUSE TestTombstonedObjectOfferedWithoutWaiting583=== RUN TestGCSweepDeliversEachKeyOnce584=== PAUSE TestGCSweepDeliversEachKeyOnce585=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection586=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection587=== RUN TestForceGCDuringPushOffersSweptObject588=== PAUSE TestForceGCDuringPushOffersSweptObject589=== RUN TestFailedS3DeleteKeepsTombstone590=== PAUSE TestFailedS3DeleteKeepsTombstone591=== RUN TestSweepSkipsRowsLockedByPush592=== PAUSE TestSweepSkipsRowsLockedByPush593=== RUN TestRegisterCompletedObjectNeedsPendingRow594=== PAUSE TestRegisterCompletedObjectNeedsPendingRow595=== RUN TestGetExistingObjectsLocksRows596=== PAUSE TestGetExistingObjectsLocksRows597=== RUN TestSweepRechecksPendingAfterLocking598=== PAUSE TestSweepRechecksPendingAfterLocking599=== RUN TestPushWaitsForSweepHoldingRow600=== PAUSE TestPushWaitsForSweepHoldingRow601=== RUN TestCommitRacingPendingCleanupKeepsObjects602=== PAUSE TestCommitRacingPendingCleanupKeepsObjects603=== RUN TestGCEndsOnShutdown604=== PAUSE TestGCEndsOnShutdown605=== RUN TestGCTaskStore_StartNew606=== PAUSE TestGCTaskStore_StartNew607=== RUN TestGCTaskStore_DeduplicateSameParams608=== PAUSE TestGCTaskStore_DeduplicateSameParams609=== RUN TestGCTaskStore_ConflictDifferentParams610=== PAUSE TestGCTaskStore_ConflictDifferentParams611=== RUN TestGCTaskStore_GetEmpty612=== PAUSE TestGCTaskStore_GetEmpty613=== RUN TestGCTaskStore_GetReturnsLatest614=== PAUSE TestGCTaskStore_GetReturnsLatest615=== RUN TestGCTaskStore_CompletedAllowsNewTask616=== PAUSE TestGCTaskStore_CompletedAllowsNewTask617=== RUN TestGCTaskStore_PhaseUpdates618=== PAUSE TestGCTaskStore_PhaseUpdates619=== RUN TestGCTaskStore_Fail620=== PAUSE TestGCTaskStore_Fail621=== RUN TestGracefulShutdownDrainsInflight622=== PAUSE TestGracefulShutdownDrainsInflight623=== RUN TestService_healthCheckHandler624=== PAUSE TestService_healthCheckHandler625=== RUN TestService_readinessHandler626=== PAUSE TestService_readinessHandler627=== RUN TestGenerateLandingPage628=== PAUSE TestGenerateLandingPage629=== RUN TestEnsureAbortUploadsRule630=== PAUSE TestEnsureAbortUploadsRule631=== RUN TestCacheConfigHandlerMaxNarSize632=== PAUSE TestCacheConfigHandlerMaxNarSize633=== RUN TestCreatePendingClosureRejectsOversizedNAR634=== PAUSE TestCreatePendingClosureRejectsOversizedNAR635=== RUN TestNARDeduplicationMetadataUploadBug636=== PAUSE TestNARDeduplicationMetadataUploadBug637=== RUN TestMetricsInventory638=== PAUSE TestMetricsInventory639=== RUN TestMetricsCommit640=== PAUSE TestMetricsCommit641=== RUN TestService_NativeMTLS642=== PAUSE TestService_NativeMTLS643=== RUN TestServerTLSConfig644=== PAUSE TestServerTLSConfig645=== RUN TestMultipartCleanup646=== PAUSE TestMultipartCleanup647=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded648=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded649=== RUN TestPendingCleanupUsesOneCutoff650=== PAUSE TestPendingCleanupUsesOneCutoff651=== RUN TestObjectStatsTrigger652=== PAUSE TestObjectStatsTrigger653=== RUN TestObjectStatsUpdatedOncePerCommit654=== PAUSE TestObjectStatsUpdatedOncePerCommit655=== RUN TestOrphanedObjectsGC656=== PAUSE TestOrphanedObjectsGC657=== RUN TestOrphanedObjectsGCStressTest658=== PAUSE TestOrphanedObjectsGCStressTest659=== RUN TestCreatePin_ReservedPins660=== PAUSE TestCreatePin_ReservedPins661=== RUN TestPresentReportsOnlyClosureRoots662=== PAUSE TestPresentReportsOnlyClosureRoots663=== RUN TestPresentRefreshesOnlyStaleClosures664=== PAUSE TestPresentRefreshesOnlyStaleClosures665=== RUN TestPresentNotReportedWhileGCDeletesClosure666=== PAUSE TestPresentNotReportedWhileGCDeletesClosure667=== RUN TestParseSingleRange668=== PAUSE TestParseSingleRange669=== RUN TestProxyHeadersOnlyTrustedOnSocket6702026/11/11 22:22:38 INFO Starting HTTP server address=127.0.0.1:396556712026/11/11 22:22:38 INFO Starting HTTP server address=proxy.sock6722026/11/11 22:22:38 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6732026/11/11 22:22:38 INFO Shutdown signal received, draining in-flight requests timeout=10s674--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.10s)675=== RUN TestIsValidCachePath676=== PAUSE TestIsValidCachePath677=== RUN TestReadProxyNarinfo678=== PAUSE TestReadProxyNarinfo679=== RUN TestReadProxyNarinfoAlreadyDecompressed680=== PAUSE TestReadProxyNarinfoAlreadyDecompressed681=== RUN TestReadProxyContentNegotiation682=== PAUSE TestReadProxyContentNegotiation683=== RUN TestReadProxyNarStreaming684=== PAUSE TestReadProxyNarStreaming685=== RUN TestReadProxy404686=== PAUSE TestReadProxy404687=== RUN TestReadProxyInvalidPath688=== PAUSE TestReadProxyInvalidPath689=== RUN TestReadProxyHead690=== PAUSE TestReadProxyHead691=== RUN TestReadProxyOutlastsServerWriteTimeout692=== PAUSE TestReadProxyOutlastsServerWriteTimeout693=== RUN TestReadProxyConditionalGet694=== PAUSE TestReadProxyConditionalGet695=== RUN TestReadProxyRootRedirectsToIndexHTML696=== PAUSE TestReadProxyRootRedirectsToIndexHTML697=== RUN TestReadProxyDisabled698=== PAUSE TestReadProxyDisabled699=== RUN TestReadRedirectNar700=== PAUSE TestReadRedirectNar701=== RUN TestReadRedirectKeepsNarinfoProxied702=== PAUSE TestReadRedirectKeepsNarinfoProxied703=== RUN TestReadProxyRangeRequest704=== PAUSE TestReadProxyRangeRequest705=== RUN TestReadRedirectUsesPublicS3URL706=== PAUSE TestReadRedirectUsesPublicS3URL707=== RUN TestPush_OverlappingRootsStoreOneRowPerKey708=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey709=== RUN TestPush_CompleteCommitsEveryRoot710=== PAUSE TestPush_CompleteCommitsEveryRoot711=== RUN TestPush_RepeatedRootCommitsOnce712=== PAUSE TestPush_RepeatedRootCommitsOnce713=== RUN TestPush_CompleteWaitsForCleanupOfThePush714=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush715=== RUN TestPush_RootsAreLockedInByteOrder716=== PAUSE TestPush_RootsAreLockedInByteOrder717=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit718=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit719=== RUN TestPush_RejectsBadRequests720=== PAUSE TestPush_RejectsBadRequests721=== RUN TestPush_SignsNarinfosOfItsPendingObjects722=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects723=== RUN TestSharedNarBothUploadsComplete724=== PAUSE TestSharedNarBothUploadsComplete725=== RUN TestCompleteMultipartUpload_ErrorButObjectExists726=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists727=== RUN TestCompletedNarNotReofferedAcrossClosures728=== PAUSE TestCompletedNarNotReofferedAcrossClosures729=== RUN TestPresignedUploadRegisteredBeforeCommit730=== PAUSE TestPresignedUploadRegisteredBeforeCommit731=== RUN TestService_Rustfstest732=== PAUSE TestService_Rustfstest733=== RUN TestParseSize734=== PAUSE TestParseSize735=== RUN TestSkippedUploadsHandler736=== PAUSE TestSkippedUploadsHandler737=== RUN TestSystemdListenerNotActivated738--- PASS: TestSystemdListenerNotActivated (0.00s)739=== RUN TestWatchdogBeatsWhenHealthy740--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)741=== RUN TestWatchdogSkipsWhenUnhealthy7422026/11/11 22:22:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7432026/11/11 22:22:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7442026/11/11 22:22:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7452026/11/11 22:22:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/11 22:22:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/11 22:22:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7482026/11/11 22:22:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7492026/11/11 22:22:38 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7502026/11/11 22:22:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7512026/11/11 22:22:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"752--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)753=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle754=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle755=== RUN TestProxyWriteTimeout756=== PAUSE TestProxyWriteTimeout757=== RUN TestPendingClosureWriteTimeout758=== PAUSE TestPendingClosureWriteTimeout759=== RUN TestIsValidUploadKey760=== PAUSE TestIsValidUploadKey761=== RUN TestUploadHandlersRejectInvalidKeys762=== PAUSE TestUploadHandlersRejectInvalidKeys763=== RUN TestUploadHandlersRejectOversizedBody764=== PAUSE TestUploadHandlersRejectOversizedBody765=== RUN TestService_cleanupPendingClosuresHandler766=== PAUSE TestService_cleanupPendingClosuresHandler767=== RUN TestService_createPendingClosureHandler768=== PAUSE TestService_createPendingClosureHandler769=== RUN TestService_verifyS3Integrity770=== PAUSE TestService_verifyS3Integrity771=== RUN TestService_verifyS3ReuploadsStaleNarinfo772=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo773=== RUN TestCompleteMultipartUnregistered774=== PAUSE TestCompleteMultipartUnregistered775=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT776=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT777=== CONT TestAbortSucceeded778=== CONT TestSharedNarBothUploadsComplete779--- PASS: TestAbortSucceeded (0.00s)780=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT781=== CONT TestCompleteMultipartUnregistered782=== CONT TestService_verifyS3ReuploadsStaleNarinfo783=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed784=== CONT TestService_verifyS3Integrity785=== CONT TestService_createPendingClosureHandler786=== CONT TestService_cleanupPendingClosuresHandler787=== CONT TestUploadHandlersRejectOversizedBody788=== CONT TestUploadHandlersRejectInvalidKeys789=== CONT TestIsValidUploadKey790=== RUN TestIsValidUploadKey/narinfo791=== PAUSE TestIsValidUploadKey/narinfo792=== CONT TestPendingClosureWriteTimeout793=== CONT TestProxyWriteTimeout794=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle795=== CONT TestSkippedUploadsHandler796=== CONT TestParseSize797=== CONT TestService_Rustfstest798=== CONT TestPresignedUploadRegisteredBeforeCommit799=== CONT TestCompletedNarNotReofferedAcrossClosures800=== CONT TestCompleteMultipartUpload_ErrorButObjectExists801=== CONT TestPresentReportsOnlyClosureRoots802=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection803=== CONT TestGCSweepDeliversEachKeyOnce804=== CONT TestTombstonedObjectOfferedWithoutWaiting805=== CONT TestForceGCDuringPushOffersSweptObject806=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed807=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info808=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info809=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal810=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal811=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key812=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key813=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key814=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key815=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows816=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows817=== RUN TestIsValidUploadKey/nar_zst818=== RUN TestProxyWriteTimeout/narinfo819--- PASS: TestParseSize (0.00s)8202026/11/11 22:22:39 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000821=== CONT TestGCSweepSkipsPendingObjects822=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check823=== CONT TestDeduplicatedObjectsRecordedAsPending824=== RUN TestPendingClosureWriteTimeout/empty825=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed826=== PAUSE TestPendingClosureWriteTimeout/empty827=== RUN TestPendingClosureWriteTimeout/400_objects828=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check829=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed830=== PAUSE TestPendingClosureWriteTimeout/400_objects831=== PAUSE TestProxyWriteTimeout/narinfo832=== PAUSE TestIsValidUploadKey/nar_zst833=== RUN TestIsValidUploadKey/nar_xz834=== PAUSE TestIsValidUploadKey/nar_xz835=== RUN TestIsValidUploadKey/nar_plain836=== PAUSE TestIsValidUploadKey/nar_plain837=== RUN TestIsValidUploadKey/listing838=== PAUSE TestIsValidUploadKey/listing839=== CONT TestPushDedupSurvivesConcurrentGC840=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost841=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost842=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed843=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed844=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed845=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed846=== CONT TestGCMetrics847=== RUN TestPendingClosureWriteTimeout/670k_objects848=== PAUSE TestPendingClosureWriteTimeout/670k_objects849=== RUN TestProxyWriteTimeout/1_GiB_nar850=== RUN TestIsValidUploadKey/build_log851=== PAUSE TestIsValidUploadKey/build_log852=== RUN TestIsValidUploadKey/build_log_home-manager_file853=== PAUSE TestIsValidUploadKey/build_log_home-manager_file854=== RUN TestIsValidUploadKey/build_log_plus_in_name855=== PAUSE TestIsValidUploadKey/build_log_plus_in_name856=== RUN TestIsValidUploadKey/build_log_question_mark857=== PAUSE TestProxyWriteTimeout/1_GiB_nar858=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline859=== PAUSE TestIsValidUploadKey/build_log_question_mark860=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline861=== RUN TestProxyWriteTimeout/10_GiB_nar862--- PASS: TestSkippedUploadsHandler (0.09s)863=== RUN TestIsValidUploadKey/build_log_equals864=== PAUSE TestIsValidUploadKey/build_log_equals865=== CONT TestGCBugBareHashReferences866=== PAUSE TestProxyWriteTimeout/10_GiB_nar867=== RUN TestProxyWriteTimeout/unknown_size868=== PAUSE TestProxyWriteTimeout/unknown_size869=== CONT TestGCAdvisoryLockBlocksConcurrentRun870=== RUN TestIsValidUploadKey/realisation871=== PAUSE TestIsValidUploadKey/realisation872=== CONT TestLeadEndsOnShutdown873=== RUN TestIsValidUploadKey/realisation_plus_in_output874=== PAUSE TestIsValidUploadKey/realisation_plus_in_output875=== RUN TestIsValidUploadKey/nix-cache-info876=== PAUSE TestIsValidUploadKey/nix-cache-info877=== RUN TestIsValidUploadKey/index.html878=== PAUSE TestIsValidUploadKey/index.html879=== RUN TestIsValidUploadKey/narinfo_key,_nar_type880=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type881=== RUN TestIsValidUploadKey/nar_key,_narinfo_type882=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type883=== RUN TestIsValidUploadKey/listing_key,_narinfo_type884=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type885=== RUN TestIsValidUploadKey/traversal886=== PAUSE TestIsValidUploadKey/traversal887=== RUN TestIsValidUploadKey/traversal_nar888=== PAUSE TestIsValidUploadKey/traversal_nar889=== RUN TestIsValidUploadKey/absolute890=== PAUSE TestIsValidUploadKey/absolute891=== RUN TestIsValidUploadKey/empty_key892=== PAUSE TestIsValidUploadKey/empty_key893=== RUN TestIsValidUploadKey/unknown_type894=== PAUSE TestIsValidUploadKey/unknown_type895=== CONT TestLeadGenerationGrowsWithEveryGrant896=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure897=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure898=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart899=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart900=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts901=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts902=== CONT TestLeadIncumbentAnnouncesAtOnce9032026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9042026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9052026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9062026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9072026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9082026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures909--- PASS: TestService_Rustfstest (0.40s)910=== CONT TestLeadUnannouncedStandbyYieldsToIncumbent9112026/11/11 22:22:39 INFO Received cleanup request method=DELETE path=/api/pending_closures9122026/11/11 22:22:39 INFO Aborted multipart uploads count=0 kept=09132026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9142026/11/11 22:22:39 INFO Received cleanup request method=DELETE path=/api/pending_closures9152026/11/11 22:22:39 INFO Aborted multipart uploads count=1 kept=09162026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9172026/11/11 22:22:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9182026-11-11 22:22:39.489 UTC [652] ERROR: Closure does not exist: id=19192026-11-11 22:22:39.489 UTC [652] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9202026-11-11 22:22:39.489 UTC [652] STATEMENT: -- name: CommitPendingClosure :one921 SELECT commit_pending_closure($1::bigint)::bigint922 923--- PASS: TestService_cleanupPendingClosuresHandler (0.45s)924=== CONT TestLeadElectsOneAndHandsOver9252026/11/11 22:22:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete926--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (0.47s)927=== CONT TestConnectWaitsForAPeerMigration9282026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9292026/11/11 22:22:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9302026/11/11 22:22:39 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst931--- PASS: TestCompleteMultipartUnregistered (0.50s)932=== CONT TestResolveDBConnectionString933=== RUN TestResolveDBConnectionString/flag_wins934=== PAUSE TestResolveDBConnectionString/flag_wins935=== RUN TestResolveDBConnectionString/file_when_flag_empty936=== PAUSE TestResolveDBConnectionString/file_when_flag_empty937=== RUN TestResolveDBConnectionString/missing_file_is_an_error938=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error939=== RUN TestResolveDBConnectionString/PGHOST_allows_empty940=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty941=== RUN TestResolveDBConnectionString/nothing_configured942=== PAUSE TestResolveDBConnectionString/nothing_configured943=== CONT TestCreatePin_ReservedPins9442026/11/11 22:22:39 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9452026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures946--- PASS: TestPresignedUploadRegisteredBeforeCommit (0.51s)947=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock9482026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9492026/11/11 22:22:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43865/oidc9502026/11/11 22:22:39 INFO Aborted multipart uploads count=0 kept=09512026/11/11 22:22:39 WARN Force mode enabled - objects will be deleted immediately without grace period9522026/11/11 22:22: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=09532026/11/11 22:22:39 INFO Aborted multipart uploads count=0 kept=09542026/11/11 22:22:39 WARN Force mode enabled - objects will be deleted immediately without grace period9552026/11/11 22:22: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=09562026/11/11 22:22:39 INFO Vacuumed table table=pending_closures9572026/11/11 22:22:39 INFO Vacuumed table table=pending_objects9582026/11/11 22:22:39 INFO Vacuumed table table=multipart_uploads9592026/11/11 22:22:39 INFO Vacuumed table table=closures9602026/11/11 22:22:39 INFO Vacuumed table table=objects9612026/11/11 22:22:39 INFO Vacuumed table table=pending_closures962--- PASS: TestGCMetrics (0.49s)963=== CONT TestDeleteClosuresRacingPins9642026/11/11 22:22:39 INFO Vacuumed table table=pending_objects9652026/11/11 22:22:39 INFO Vacuumed table table=multipart_uploads9662026/11/11 22:22:39 INFO Vacuumed table table=closures9672026/11/11 22:22:39 INFO Vacuumed table table=objects9682026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures969--- PASS: TestGCSweepSkipsPendingObjects (0.60s)970=== CONT TestClientFallsBackToClosures9712026/11/11 22:22:39 INFO lead: acquired remote=192.0.2.1:1234 generation=19722026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9732026/11/11 22:22:39 INFO Aborted multipart uploads count=0 kept=0974--- PASS: TestDeduplicatedObjectsRecordedAsPending (0.70s)975=== CONT TestOrphanedObjectsGCStressTest9762026/11/11 22:22:39 WARN Force mode enabled - objects will be deleted immediately without grace period9772026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9782026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures979--- PASS: TestTombstonedObjectOfferedWithoutWaiting (0.75s)980=== CONT TestClientPushesUseOnePush9812026/11/11 22:22: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=09822026/11/11 22:22:39 INFO Vacuumed table table=pending_closures9832026/11/11 22:22:39 INFO Vacuumed table table=pending_objects9842026/11/11 22:22:39 INFO Vacuumed table table=multipart_uploads9852026/11/11 22:22:39 INFO Vacuumed table table=closures9862026/11/11 22:22:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9872026/11/11 22:22:39 INFO Vacuumed table table=objects988--- PASS: TestGCSweepDeliversEachKeyOnce (0.76s)989=== CONT TestPinProtectsFromGC9902026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9912026/11/11 22:22:39 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLmZjMmMwZDlmLTFiMDctNGVhYi05MWQ1LTVlMDBmZmUyZDQ0NXgxNzk0NDM1NzU5MzkxMzY4MDkz parts=109922026/11/11 22:22:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9932026/11/11 22:22:39 INFO Completed upload id=1 objects=2 duration=3.3174ms9942026/11/11 22:22:39 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000009952026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures9962026/11/11 22:22:39 INFO Starting cleanup of old closures method=DELETE path=/api/closures9972026/11/11 22:22:39 INFO Aborted multipart uploads count=0 kept=09982026/11/11 22:22: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=09992026/11/11 22:22:39 INFO lead: acquired remote=192.0.2.1:1234 generation=110002026/11/11 22:22:39 INFO Vacuumed table table=pending_closures10012026/11/11 22:22:39 INFO Vacuumed table table=pending_objects10022026/11/11 22:22:39 INFO Vacuumed table table=multipart_uploads10032026/11/11 22:22:39 INFO Vacuumed table table=closures10042026/11/11 22:22:39 INFO Vacuumed table table=objects10052026/11/11 22:22:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10062026/11/11 22:22:39 INFO lead: acquired remote=192.0.2.1:1234 generation=110072026/11/11 22:22:39 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010082026/11/11 22:22:39 INFO lead: released remote=192.0.2.1:1234 generation=11009--- PASS: TestLeadIncumbentAnnouncesAtOnce (0.68s)1010=== CONT TestOrphanedObjectsGC1011--- PASS: TestService_createPendingClosureHandler (0.85s)1012=== CONT TestClientSharedPathCommittedMidPush10132026/11/11 22:22:39 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLjFlOTI1NmYwLWRiODUtNDA5Yy04NGVmLTZlNTJhZDZkMDhkOXgxNzk0NDM1NzU5MzY5ODg4MTYy parts=121014--- PASS: TestPresentReportsOnlyClosureRoots (0.88s)1015=== CONT TestObjectStatsUpdatedOncePerCommit10162026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures10172026/11/11 22:22:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10182026/11/11 22:22:39 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLmM5ZGM1OGQ1LTdmZTMtNDY5Mi05ODI0LTgxMWMwMjE1OGM5ZngxNzk0NDM1NzU5OTQ1NTAxMDA410192026/11/11 22:22:39 INFO Received uploads request method=POST path=/api/pending_closures10202026/11/11 22:22: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"1021--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (0.86s)1022=== CONT TestClientWithDependencies10232026/11/11 22:22:39 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLmM5ZGM1OGQ1LTdmZTMtNDY5Mi05ODI0LTgxMWMwMjE1OGM5ZngxNzk0NDM1NzU5OTQ1NTAxMDA4 parts=11024--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (0.96s)1025=== CONT TestClientMultipleUploads1026--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (1.00s)1027=== CONT TestObjectStatsTrigger10282026/11/11 22:22:40 INFO lead: acquired remote=192.0.2.1:1234 generation=110292026/11/11 22:22:40 INFO Aborted multipart uploads count=0 kept=010302026/11/11 22:22:40 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=010312026/11/11 22:22:40 INFO Vacuumed table table=pending_closures10322026/11/11 22:22:40 INFO Vacuumed table table=pending_objects10332026/11/11 22:22:40 INFO Vacuumed table table=multipart_uploads10342026/11/11 22:22:40 INFO lead: acquired remote=192.0.2.1:1234 generation=110352026/11/11 22:22:40 INFO Vacuumed table table=closures10362026/11/11 22:22:40 INFO Vacuumed table table=objects10372026/11/11 22:22:40 INFO Aborted multipart uploads count=0 kept=010382026/11/11 22:22:40 WARN Force mode enabled - objects will be deleted immediately without grace period10392026/11/11 22:22: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=010402026/11/11 22:22:40 INFO Vacuumed table table=pending_closures10412026/11/11 22:22:40 INFO Vacuumed table table=pending_objects10422026/11/11 22:22:40 INFO Vacuumed table table=multipart_uploads10432026/11/11 22:22:40 INFO Vacuumed table table=closures10442026/11/11 22:22:40 INFO Vacuumed table table=objects1045--- PASS: TestPushDedupSurvivesConcurrentGC (0.98s)1046=== CONT TestClientIntegration10472026/11/11 22:22:40 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10482026/11/11 22:22:40 WARN Refused reserved pin name=worker-x86_64-linux10492026/11/11 22:22:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10502026/11/11 22:22:40 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10512026/11/11 22:22:40 INFO Received create pin request method=POST path=/api/pins/my-app10522026/11/11 22:22:40 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1053--- PASS: TestCreatePin_ReservedPins (0.61s)1054=== CONT TestPendingCleanupUsesOneCutoff10552026/11/11 22:22:40 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLjI2ZDdjMGFiLWUyNTctNGIxOS1iOTE1LTg0NDA4NTY4NGQ1N3gxNzk0NDM1NzU5NjUwNTMzNTY1 parts=1210562026/11/11 22:22:40 INFO Received uploads request method=POST path=/api/pending_closures1057--- PASS: TestCompletedNarNotReofferedAcrossClosures (1.14s)1058=== CONT TestClientErrorHandling1059=== RUN TestClientErrorHandling/InvalidStorePath1060=== PAUSE TestClientErrorHandling/InvalidStorePath1061=== RUN TestClientErrorHandling/InvalidAuthToken1062=== PAUSE TestClientErrorHandling/InvalidAuthToken1063=== RUN TestClientErrorHandling/ServerNotAvailable1064=== PAUSE TestClientErrorHandling/ServerNotAvailable1065=== CONT TestClientCADerivations10662026/11/11 22:22:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10672026/11/11 22:22:40 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLjNhMmFkZGU5LTJmNWYtNDI1NC1iN2Y4LTQzNThjMWQxZGJmNHgxNzk0NDM1NzU5Nzk0MDU1NDE3 parts=1010682026/11/11 22:22:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10692026/11/11 22:22:40 INFO Completed upload id=1 objects=2 duration=5.55534ms10702026/11/11 22:22:40 INFO Received uploads request method=POST path=/api/pending_closures10712026/11/11 22:22:40 INFO Received uploads request method=POST path=/api/pending_closures10722026/11/11 22:22:40 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10732026/11/11 22:22:40 WARN Found objects in DB but missing from S3, will re-upload count=11074--- PASS: TestService_verifyS3Integrity (1.21s)1075=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1076--- PASS: TestGCBugBareHashReferences (1.12s)1077=== CONT TestCacheStatsHandler1078--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (0.79s)1079=== CONT TestMultipartCleanup1080=== NAME TestPinProtectsFromGC1081 client_integration_test.go:778: Pinned store path: /build/TestPinProtectsFromGC479254395/001/store/7szdnnwm4lhqfbm7zn6ai8l3wf9zrwdx-pinned-file.txt1082 client_integration_test.go:779: Unpinned store path: /build/TestPinProtectsFromGC479254395/001/store/20gfih08sk30dy72j44is5fcdrrl4i37-unpinned-file.txt10832026/11/11 22:22:40 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10842026/11/11 22:22:40 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLmNiZTE3YjMxLWQ4YWQtNDFjZC1iMTg5LTgwYjEyZTVhNjgyOHgxNzk0NDM1NzU5MzgzODUzNzAz parts=121085--- PASS: TestSharedNarBothUploadsComplete (1.35s)1086=== CONT TestCacheConfigHandler1087=== RUN TestCacheConfigHandler/full_config,_no_issuer1088=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1089=== RUN TestCacheConfigHandler/no_cache_url_configured1090=== PAUSE TestCacheConfigHandler/no_cache_url_configured1091=== RUN TestCacheConfigHandler/no_signing_keys1092=== PAUSE TestCacheConfigHandler/no_signing_keys1093=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1094=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1095=== CONT TestServerTLSConfig1096=== RUN TestServerTLSConfig/no_client_CA1097=== PAUSE TestServerTLSConfig/no_client_CA1098=== RUN TestServerTLSConfig/missing_CA_file1099=== PAUSE TestServerTLSConfig/missing_CA_file1100=== RUN TestServerTLSConfig/not_a_PEM_file1101=== PAUSE TestServerTLSConfig/not_a_PEM_file1102=== CONT TestService_ReadScope_PublicByDefault11032026/11/11 22:22:40 INFO Received uploads request method=POST path=/api/pending_closures11042026/11/11 22:22:40 INFO Received uploads request method=POST path=/api/pending_closures1105--- PASS: TestObjectStatsUpdatedOncePerCommit (0.49s)1106=== CONT TestService_NativeMTLS11072026/11/11 22:22:40 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11082026/11/11 22:22:40 INFO Uploading 7ml8g9y9vmr4702dx1y22mn8qqj2yn4j-b (216B)11092026/11/11 22:22:40 INFO Uploading mxw337ijfvfg06q8lisikcwzivhkxgpy-shared-dep (136B)11102026/11/11 22:22:40 WARN Failed to register uploaded object key=7ml8g9y9vmr4702dx1y22mn8qqj2yn4j.ls error="server returned 404: 404 page not found\n"11112026/11/11 22:22:40 WARN Failed to register uploaded object key=1q0wm0s5bfmmbh1s5iil8wg3xs56dd29.ls error="server returned 404: 404 page not found\n"11122026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/1kfxwblk0l7b0mr51xylksm51gsrvm9fz5p3vricwpym7yll0vfr.nar.zst error="server returned 404: 404 page not found\n"11132026/11/11 22:22:40 WARN Failed to register uploaded object key=mxw337ijfvfg06q8lisikcwzivhkxgpy.ls error="server returned 404: 404 page not found\n"11142026/11/11 22:22:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign11152026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11162026/11/11 22:22:40 INFO Signed narinfos id=1 count=211172026/11/11 22:22:40 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign11182026/11/11 22:22:40 INFO Signed narinfos id=2 count=211192026/11/11 22:22:40 INFO Uploading 4 narinfos11202026/11/11 22:22:40 INFO Received push request method=POST path=/api/pushes11212026/11/11 22:22:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11222026/11/11 22:22:40 INFO Uploading 7szdnnwm4lhqfbm7zn6ai8l3wf9zrwdx-pinned-file.txt (128B)11232026/11/11 22:22:40 WARN Failed to register uploaded object key=1q0wm0s5bfmmbh1s5iil8wg3xs56dd29.narinfo error="server returned 404: 404 page not found\n"11242026/11/11 22:22:40 WARN Failed to register uploaded object key=mxw337ijfvfg06q8lisikcwzivhkxgpy.narinfo error="server returned 404: 404 page not found\n"11252026/11/11 22:22:40 WARN Failed to register uploaded object key=7ml8g9y9vmr4702dx1y22mn8qqj2yn4j.narinfo error="server returned 404: 404 page not found\n"11262026/11/11 22:22:40 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11272026/11/11 22:22:40 WARN Failed to register uploaded object key=mxw337ijfvfg06q8lisikcwzivhkxgpy.narinfo error="server returned 404: 404 page not found\n"11282026/11/11 22:22:40 WARN Failed to register uploaded object key=7szdnnwm4lhqfbm7zn6ai8l3wf9zrwdx.ls error="server returned 404: 404 page not found\n"11292026/11/11 22:22:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11302026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"11312026/11/11 22:22:40 INFO Signed narinfos id=1 count=111322026/11/11 22:22:40 INFO Uploading 1 narinfos11332026/11/11 22:22:40 INFO Completed upload id=1 objects=6 duration=5.63697ms11342026/11/11 22:22:40 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11352026/11/11 22:22:40 INFO Received complete push request method=POST path=/api/pushes/1/complete11362026/11/11 22:22:40 WARN Failed to register uploaded object key=7szdnnwm4lhqfbm7zn6ai8l3wf9zrwdx.narinfo error="server returned 404: 404 page not found\n"11372026/11/11 22:22:40 INFO Completed upload id=2 objects=6 duration=1.71526ms11382026/11/11 22:22:40 INFO Upload complete. (88ms)1139=== NAME TestClientFallsBackToClosures1140 client_pushes_test.go:112: Retrieved narinfo from S3:1141 StorePath: /build/TestClientFallsBackToClosures2013818952/001/store/mxw337ijfvfg06q8lisikcwzivhkxgpy-shared-dep1142 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1143 Compression: zstd1144 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821145 NarSize: 1361146 References: 1147 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n11482026/11/11 22:22:40 INFO Completed push id=1 objects=3 duration=4.88655ms11492026/11/11 22:22:40 INFO Received push request method=POST path=/api/pushes11502026/11/11 22:22:40 INFO Upload complete. (59ms)1151 client_pushes_test.go:112: Retrieved narinfo from S3:1152 StorePath: /build/TestClientFallsBackToClosures2013818952/001/store/1q0wm0s5bfmmbh1s5iil8wg3xs56dd29-a1153 URL: nar/1kfxwblk0l7b0mr51xylksm51gsrvm9fz5p3vricwpym7yll0vfr.nar.zst1154 Compression: zstd1155 NarHash: sha256:1kfxwblk0l7b0mr51xylksm51gsrvm9fz5p3vricwpym7yll0vfr1156 NarSize: 2161157 References: /build/TestClientFallsBackToClosures2013818952/001/store/mxw337ijfvfg06q8lisikcwzivhkxgpy-shared-dep1158 CA: text:sha256:0gdbpzd9cxis7srmbqjca9k2f7sj4mm1mxs90dn4hcvwyjsl22as11592026/11/11 22:22:40 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)11602026/11/11 22:22:40 INFO Uploading m2rk0vnmqzwmdqfc01asxja725bvjifd-b (216B)11612026/11/11 22:22:40 INFO Uploading 06i8s0dn539dq0gw4vb6n280pccnrwri-shared-dep (136B)1162 client_pushes_test.go:112: Retrieved narinfo from S3:1163 StorePath: /build/TestClientFallsBackToClosures2013818952/001/store/7ml8g9y9vmr4702dx1y22mn8qqj2yn4j-b1164 URL: nar/1kfxwblk0l7b0mr51xylksm51gsrvm9fz5p3vricwpym7yll0vfr.nar.zst1165 Compression: zstd1166 NarHash: sha256:1kfxwblk0l7b0mr51xylksm51gsrvm9fz5p3vricwpym7yll0vfr1167 NarSize: 2161168 References: /build/TestClientFallsBackToClosures2013818952/001/store/mxw337ijfvfg06q8lisikcwzivhkxgpy-shared-dep1169 CA: text:sha256:0gdbpzd9cxis7srmbqjca9k2f7sj4mm1mxs90dn4hcvwyjsl22as11702026/11/11 22:22:40 WARN Failed to register uploaded object key=m2rk0vnmqzwmdqfc01asxja725bvjifd.ls error="server returned 404: 404 page not found\n"11712026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/0xh0jw27mg4m27imynn5f0n6ldiasvisk8rr5c49767pcj6kgpxa.nar.zst error="server returned 404: 404 page not found\n"11722026/11/11 22:22:40 WARN Failed to register uploaded object key=06i8s0dn539dq0gw4vb6n280pccnrwri.ls error="server returned 404: 404 page not found\n"11732026/11/11 22:22:40 WARN Failed to register uploaded object key=3ynzdvvnk1mmjp6ld4csaccfvgg6kspg.ls error="server returned 404: 404 page not found\n"11742026/11/11 22:22:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11752026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11762026/11/11 22:22:40 INFO Signed narinfos id=1 count=311772026/11/11 22:22:40 INFO Uploading 3 narinfos1178--- PASS: TestClientFallsBackToClosures (0.82s)1179=== CONT TestService_RequireScope_OIDC11802026/11/11 22:22:40 WARN Failed to register uploaded object key=m2rk0vnmqzwmdqfc01asxja725bvjifd.narinfo error="server returned 404: 404 page not found\n"11812026/11/11 22:22:40 WARN Failed to register uploaded object key=06i8s0dn539dq0gw4vb6n280pccnrwri.narinfo error="server returned 404: 404 page not found\n"11822026/11/11 22:22:40 INFO Received complete push request method=POST path=/api/pushes/1/complete11832026/11/11 22:22:40 WARN Failed to register uploaded object key=3ynzdvvnk1mmjp6ld4csaccfvgg6kspg.narinfo error="server returned 404: 404 page not found\n"11842026/11/11 22:22:40 INFO Completed push id=1 objects=8 duration=5.78628ms11852026/11/11 22:22:40 INFO Upload complete. (62ms)1186=== NAME TestClientMultipleUploads1187 client_integration_test.go:405: Created store path 0: /build/TestClientMultipleUploads2872881299/001/store/bxl9pfsa5xiqjn56fy11415q1hp37v4p-test-file-0.txt1188=== NAME TestClientPushesUseOnePush1189 client_pushes_test.go:97: Retrieved narinfo from S3:1190 StorePath: /build/TestClientPushesUseOnePush1448797686/001/store/06i8s0dn539dq0gw4vb6n280pccnrwri-shared-dep1191 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1192 Compression: zstd1193 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821194 NarSize: 1361195 References: 1196 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1197 client_pushes_test.go:97: Retrieved narinfo from S3:1198 StorePath: /build/TestClientPushesUseOnePush1448797686/001/store/3ynzdvvnk1mmjp6ld4csaccfvgg6kspg-a1199 URL: nar/0xh0jw27mg4m27imynn5f0n6ldiasvisk8rr5c49767pcj6kgpxa.nar.zst1200 Compression: zstd1201 NarHash: sha256:0xh0jw27mg4m27imynn5f0n6ldiasvisk8rr5c49767pcj6kgpxa1202 NarSize: 2161203 References: /build/TestClientPushesUseOnePush1448797686/001/store/06i8s0dn539dq0gw4vb6n280pccnrwri-shared-dep1204 CA: text:sha256:1kd3mnckh8s2ypzf67m8dcaihlaqzfxx14mlhniqkcr3589lyn651205--- PASS: TestObjectStatsTrigger (0.44s)1206=== CONT TestMetricsCommit1207=== NAME TestClientPushesUseOnePush1208 client_pushes_test.go:97: Retrieved narinfo from S3:1209 StorePath: /build/TestClientPushesUseOnePush1448797686/001/store/m2rk0vnmqzwmdqfc01asxja725bvjifd-b1210 URL: nar/0xh0jw27mg4m27imynn5f0n6ldiasvisk8rr5c49767pcj6kgpxa.nar.zst1211 Compression: zstd1212 NarHash: sha256:0xh0jw27mg4m27imynn5f0n6ldiasvisk8rr5c49767pcj6kgpxa1213 NarSize: 2161214 References: /build/TestClientPushesUseOnePush1448797686/001/store/06i8s0dn539dq0gw4vb6n280pccnrwri-shared-dep1215 CA: text:sha256:1kd3mnckh8s2ypzf67m8dcaihlaqzfxx14mlhniqkcr3589lyn651216=== NAME TestClientWithDependencies1217 client_integration_test.go:660: Built derivation: /build/TestClientWithDependencies587950290/001/store/qclm05sz0qsjnxxyrl3qbdzsbwkjprly-test-script1218--- PASS: TestClientPushesUseOnePush (0.69s)1219=== CONT TestService_AuthMiddleware_OIDC12202026/11/11 22:22:40 INFO Received push request method=POST path=/api/pushes12212026/11/11 22:22:40 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12222026/11/11 22:22:40 INFO Uploading 8hsa7rh9i4w6xjiyvlmvh46925p7zcgs-top (224B)12232026/11/11 22:22:40 INFO Uploading j0cw4pm3d5gp5lpndc8xg4bdl4s8lg7j-shared-dep (136B)12242026/11/11 22:22:40 WARN Failed to register uploaded object key=8hsa7rh9i4w6xjiyvlmvh46925p7zcgs.ls error="server returned 404: 404 page not found\n"12252026/11/11 22:22:40 WARN Failed to register uploaded object key=j0cw4pm3d5gp5lpndc8xg4bdl4s8lg7j.ls error="server returned 404: 404 page not found\n"12262026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/1zlwfg0s7jzzwviwf48yc9ws28gbg9ln2jcjzgc66frwp4yzcx21.nar.zst error="server returned 404: 404 page not found\n"12272026/11/11 22:22:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12282026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12292026/11/11 22:22:40 INFO Signed narinfos id=1 count=212302026/11/11 22:22:40 INFO Uploading 2 narinfos12312026/11/11 22:22:40 INFO Received uploads request method=POST path=/api/pending_closures12322026/11/11 22:22:40 WARN Failed to register uploaded object key=8hsa7rh9i4w6xjiyvlmvh46925p7zcgs.narinfo error="server returned 404: 404 page not found\n"12332026/11/11 22:22:40 INFO Received complete push request method=POST path=/api/pushes/1/complete12342026/11/11 22:22:40 WARN Failed to register uploaded object key=j0cw4pm3d5gp5lpndc8xg4bdl4s8lg7j.narinfo error="server returned 404: 404 page not found\n"1235=== NAME TestClientMultipleUploads1236 client_integration_test.go:405: Created store path 1: /build/TestClientMultipleUploads2872881299/001/store/p9zcpx7d2fsczi8b55mxahsch8ylvhw0-test-file-1.txt1237=== NAME TestClientWithDependencies1238 client_integration_test.go:662: Found 1 dependencies (including self)12392026/11/11 22:22:40 INFO Received uploads request method=POST path=/api/pending_closures12402026/11/11 22:22:40 INFO Completed push id=1 objects=6 duration=5.38866ms12412026/11/11 22:22:40 INFO Upload complete. (64ms)1242=== NAME TestClientSharedPathCommittedMidPush1243 client_integration_test.go:727: Retrieved narinfo from S3:1244 StorePath: /build/TestClientSharedPathCommittedMidPush3710356453/001/store/j0cw4pm3d5gp5lpndc8xg4bdl4s8lg7j-shared-dep1245 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1246 Compression: zstd1247 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821248 NarSize: 1361249 References: 1250 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1251 client_integration_test.go:727: Retrieved narinfo from S3:1252 StorePath: /build/TestClientSharedPathCommittedMidPush3710356453/001/store/8hsa7rh9i4w6xjiyvlmvh46925p7zcgs-top12532026/11/11 22:22:40 INFO Received push request method=POST path=/api/pushes1254 URL: nar/1zlwfg0s7jzzwviwf48yc9ws28gbg9ln2jcjzgc66frwp4yzcx21.nar.zst1255 Compression: zstd1256 NarHash: sha256:1zlwfg0s7jzzwviwf48yc9ws28gbg9ln2jcjzgc66frwp4yzcx211257 NarSize: 2241258 References: /build/TestClientSharedPathCommittedMidPush3710356453/001/store/j0cw4pm3d5gp5lpndc8xg4bdl4s8lg7j-shared-dep1259 CA: text:sha256:1fk01r0jl7rqq5ynynph3dpqaggdzi4jdlk1jkhdjbgsl7ghkvk012602026/11/11 22:22:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12612026/11/11 22:22:40 INFO Uploading 20gfih08sk30dy72j44is5fcdrrl4i37-unpinned-file.txt (128B)12622026/11/11 22:22:40 INFO Received cleanup request method=DELETE path=/api/pending_closures1263--- PASS: TestClientSharedPathCommittedMidPush (0.63s)1264=== CONT TestMetricsInventory12652026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"12662026/11/11 22:22:40 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12672026/11/11 22:22:40 WARN Failed to register uploaded object key=20gfih08sk30dy72j44is5fcdrrl4i37.ls error="server returned 404: 404 page not found\n"12682026/11/11 22:22:40 INFO Signed narinfos id=2 count=112692026/11/11 22:22:40 INFO Uploading 1 narinfos1270=== NAME TestClientIntegration1271 client_integration_test.go:291: Created store path: /build/TestClientIntegration101417261/002/store/wfz5i2hb6fv17cfg47dh7hawr944f75f-test-file.txt12722026/11/11 22:22:40 INFO Received complete push request method=POST path=/api/pushes/2/complete12732026/11/11 22:22:40 WARN Failed to register uploaded object key=20gfih08sk30dy72j44is5fcdrrl4i37.narinfo error="server returned 404: 404 page not found\n"12742026/11/11 22:22:40 INFO Completed push id=2 objects=3 duration=14.36421ms12752026/11/11 22:22:40 INFO Upload complete. (64ms)12762026/11/11 22:22:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44141/oidc1277=== NAME TestClientMultipleUploads1278 client_integration_test.go:405: Created store path 2: /build/TestClientMultipleUploads2872881299/001/store/rwpi7z29vrf2aqi7rs9a81xnpdm31bfp-test-file-2.txt1279--- PASS: TestCacheStatsHandler (0.31s)1280=== CONT TestService_ReadAuthMiddleware12812026/11/11 22:22:40 INFO Received push request method=POST path=/api/pushes12822026/11/11 22:22:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures12832026/11/11 22:22:40 INFO Received uploads request method=POST path=/api/pending_closures12842026/11/11 22:22:40 INFO Garbage collection started12852026/11/11 22:22:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12862026/11/11 22:22:40 INFO Uploading qclm05sz0qsjnxxyrl3qbdzsbwkjprly-test-script (136B)12872026/11/11 22:22:40 WARN Failed to register uploaded object key=qclm05sz0qsjnxxyrl3qbdzsbwkjprly.ls error="server returned 404: 404 page not found\n"12882026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"12892026/11/11 22:22:40 WARN Failed to register uploaded object key=log/s0xs875mpl19r8043szrb15khvdc54qi-test-script.drv error="server returned 404: 404 page not found\n"12902026/11/11 22:22:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12912026/11/11 22:22:40 INFO Received push request method=POST path=/api/pushes12922026/11/11 22:22:40 INFO Signed narinfos id=1 count=112932026/11/11 22:22:40 INFO Uploading 1 narinfos1294--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.35s)1295=== CONT TestNARDeduplicationMetadataUploadBug12962026/11/11 22:22:40 INFO Aborted multipart uploads count=0 kept=012972026/11/11 22:22:40 INFO Received complete push request method=POST path=/api/pushes/1/complete12982026/11/11 22:22:40 WARN Failed to register uploaded object key=qclm05sz0qsjnxxyrl3qbdzsbwkjprly.narinfo error="server returned 404: 404 page not found\n"12992026/11/11 22:22:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13002026/11/11 22:22:40 INFO Uploading wfz5i2hb6fv17cfg47dh7hawr944f75f-test-file.txt (152B)13012026/11/11 22:22:40 WARN Force mode enabled - objects will be deleted immediately without grace period13022026/11/11 22:22:40 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37093/oidc13032026/11/11 22:22:40 INFO Received uploads request method=POST path=/api/pending_closures13042026/11/11 22:22:40 INFO Completed push id=1 objects=4 duration=9.70926ms13052026/11/11 22:22:40 WARN Failed to register uploaded object key=wfz5i2hb6fv17cfg47dh7hawr944f75f.ls error="server returned 404: 404 page not found\n"13062026/11/11 22:22:40 INFO Upload complete. (69ms)13072026/11/11 22:22:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13082026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"13092026/11/11 22:22:40 INFO Signed narinfos id=1 count=113102026/11/11 22:22:40 INFO Uploading 1 narinfos1311=== NAME TestClientWithDependencies1312 client_integration_test.go:664: Skipping nix copy test - isolated store (/build/TestClientWithDependencies587950290/001/store) requires matching store prefix13132026/11/11 22:22:40 INFO Received complete push request method=POST path=/api/pushes/1/complete13142026/11/11 22:22:40 WARN Failed to register uploaded object key=wfz5i2hb6fv17cfg47dh7hawr944f75f.narinfo error="server returned 404: 404 page not found\n"1315--- PASS: TestClientWithDependencies (0.62s)1316=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1317=== NAME TestClientCADerivations1318 client_ca_test.go:136: Built CA derivation: /build/TestClientCADerivations321690630/001/store/kbpb8jd670rgmy7a6x33i3v4z18lhxdc-ca-test13192026/11/11 22:22:40 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13202026/11/11 22:22:40 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1321--- PASS: TestService_NativeMTLS (0.22s)1322=== CONT TestCreatePendingClosureRejectsOversizedNAR13232026/11/11 22:22:40 INFO Received uploads request method=POST path=/api/pending_closures1324--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1325=== CONT TestService_AuthMiddleware_MTLSProxyHeader13262026/11/11 22:22:40 INFO Received push request method=POST path=/api/pushes13272026/11/11 22:22:40 INFO Completed push id=1 objects=3 duration=27.75124ms13282026/11/11 22:22:40 INFO Upload complete. (88ms)13292026/11/11 22:22: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=013302026/11/11 22:22:40 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)13312026/11/11 22:22:40 INFO Uploading p9zcpx7d2fsczi8b55mxahsch8ylvhw0-test-file-1.txt (160B)13322026/11/11 22:22:40 INFO Uploading rwpi7z29vrf2aqi7rs9a81xnpdm31bfp-test-file-2.txt (160B)13332026/11/11 22:22:40 INFO Uploading bxl9pfsa5xiqjn56fy11415q1hp37v4p-test-file-0.txt (160B)13342026/11/11 22:22:40 INFO Vacuumed table table=pending_closures1335=== NAME TestClientCADerivations1336 client_ca_test.go:139: Found 1 dependencies (including self)13372026/11/11 22:22:40 WARN Failed to register uploaded object key=rwpi7z29vrf2aqi7rs9a81xnpdm31bfp.ls error="server returned 404: 404 page not found\n"13382026/11/11 22:22:40 WARN Failed to register uploaded object key=bxl9pfsa5xiqjn56fy11415q1hp37v4p.ls error="server returned 404: 404 page not found\n"13392026/11/11 22:22:40 INFO Vacuumed table table=pending_objects13402026/11/11 22:22:40 WARN Failed to register uploaded object key=p9zcpx7d2fsczi8b55mxahsch8ylvhw0.ls error="server returned 404: 404 page not found\n"13412026/11/11 22:22:40 INFO Vacuumed table table=multipart_uploads13422026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"13432026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"13442026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"13452026/11/11 22:22:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13462026/11/11 22:22:40 INFO Signed narinfos id=1 count=313472026/11/11 22:22:40 INFO Uploading 3 narinfos13482026/11/11 22:22:40 INFO Vacuumed table table=closures13492026/11/11 22:22:40 WARN Failed to register uploaded object key=bxl9pfsa5xiqjn56fy11415q1hp37v4p.narinfo error="server returned 404: 404 page not found\n"13502026/11/11 22:22:40 INFO Vacuumed table table=objects13512026/11/11 22:22:40 WARN Failed to register uploaded object key=rwpi7z29vrf2aqi7rs9a81xnpdm31bfp.narinfo error="server returned 404: 404 page not found\n"1352--- PASS: TestService_ReadScope_PublicByDefault (0.30s)1353=== CONT TestService_AuthMiddleware13542026/11/11 22:22:40 INFO Received complete push request method=POST path=/api/pushes/1/complete13552026/11/11 22:22:40 WARN Failed to register uploaded object key=p9zcpx7d2fsczi8b55mxahsch8ylvhw0.narinfo error="server returned 404: 404 page not found\n"13562026/11/11 22:22:40 INFO All 1 paths already cached1357=== NAME TestClientIntegration1358 client_integration_test.go:317: Retrieved narinfo from S3:1359 StorePath: /build/TestClientIntegration101417261/002/store/wfz5i2hb6fv17cfg47dh7hawr944f75f-test-file.txt1360 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1361 Compression: zstd1362 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11363 NarSize: 1521364 References: 1365 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk113662026/11/11 22:22:40 INFO Completed push id=1 objects=9 duration=6.51148ms13672026/11/11 22:22:40 INFO Upload complete. (114ms)1368=== NAME TestClientMultipleUploads1369 client_integration_test.go:416: Uploaded 3 paths in 148.439681ms1370=== NAME TestClientIntegration1371 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1372 client_integration_test.go:318: Decompressed .ls content (64 bytes):1373 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1374--- PASS: TestClientMultipleUploads (0.71s)1375=== CONT TestCacheConfigHandlerMaxNarSize1376--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1377=== CONT TestEnsureAbortUploadsRule13782026/11/11 22:22:40 INFO Received push request method=POST path=/api/pushes13792026/11/11 22:22:40 INFO Received cleanup request method=DELETE path=/api/pending_closures13802026/11/11 22:22:40 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket48/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""13812026/11/11 22:22:40 INFO Aborted multipart uploads count=0 kept=113822026/11/11 22:22:40 INFO Received cleanup request method=DELETE path=/api/pending_closures13832026/11/11 22:22:40 INFO Aborted multipart uploads count=1 kept=01384--- PASS: TestMultipartCleanup (0.39s)1385=== CONT TestGCTaskStore_ConflictDifferentParams1386--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1387=== CONT TestGenerateLandingPage1388--- PASS: TestGenerateLandingPage (0.00s)1389=== CONT TestGCTaskStore_DeduplicateSameParams1390--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1391=== CONT TestService_readinessHandler13922026/11/11 22:22:40 INFO Received complete push request method=POST path=/api/pushes/1/complete13932026/11/11 22:22:40 INFO Completed push id=1 objects=4 duration=6.29325ms1394=== NAME TestOrphanedObjectsGC1395 orphaned_objects_gc_test.go:287: GC Test Summary:1396 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1397 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1398 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1399 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1400 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1401--- PASS: TestOrphanedObjectsGC (0.86s)1402=== CONT TestGCTaskStore_StartNew1403--- PASS: TestGCTaskStore_StartNew (0.00s)1404=== CONT TestService_healthCheckHandler14052026/11/11 22:22:40 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14062026/11/11 22:22:40 INFO Completed upload id=2 objects=2 duration=1.85572ms1407--- PASS: TestMetricsInventory (0.23s)1408=== CONT TestGCEndsOnShutdown1409=== RUN TestGCEndsOnShutdown/before_the_run1410=== PAUSE TestGCEndsOnShutdown/before_the_run1411=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1412=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1413=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1414=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1415=== CONT TestGracefulShutdownDrainsInflight14162026/11/11 22:22:40 INFO Starting HTTP server address=127.0.0.1:3618514172026/11/11 22:22:40 INFO Shutdown signal received, draining in-flight requests timeout=10s1418--- PASS: TestMetricsCommit (0.28s)1419=== CONT TestCommitRacingPendingCleanupKeepsObjects1420=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1421=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1422=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1423=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1424=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1425=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1426=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1427=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1428=== CONT TestGCTaskStore_Fail1429--- PASS: TestGCTaskStore_Fail (0.00s)1430=== CONT TestPushWaitsForSweepHoldingRow14312026/11/11 22:22:40 INFO Received push request method=POST path=/api/pushes14322026/11/11 22:22:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14332026/11/11 22:22:40 INFO Uploading kbpb8jd670rgmy7a6x33i3v4z18lhxdc-ca-test (144B)14342026/11/11 22:22:40 WARN Failed to register uploaded object key=log/z7qrgyxjf2kz3rvpsfnr8p3pmnff6c03-ca-test.drv error="server returned 404: 404 page not found\n"14352026/11/11 22:22:40 INFO Received push request method=POST path=/api/pushes14362026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14372026/11/11 22:22:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14382026/11/11 22:22:40 WARN Failed to register uploaded object key=kbpb8jd670rgmy7a6x33i3v4z18lhxdc.ls error="server returned 404: 404 page not found\n"14392026/11/11 22:22:40 INFO Signed narinfos id=1 count=114402026/11/11 22:22:40 INFO Uploading 1 narinfos1441--- PASS: TestService_ReadAuthMiddleware (0.22s)1442=== CONT TestGCTaskStore_GetReturnsLatest1443--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1444=== CONT TestSweepRechecksPendingAfterLocking14452026/11/11 22:22:40 INFO Received complete push request method=POST path=/api/pushes/1/complete14462026/11/11 22:22:40 WARN Failed to register uploaded object key=kbpb8jd670rgmy7a6x33i3v4z18lhxdc.narinfo error="server returned 404: 404 page not found\n"14472026/11/11 22:22:40 INFO Completed push id=1 objects=4 duration=17.130611ms14482026/11/11 22:22:40 INFO Object in database but missing from S3 key=wfz5i2hb6fv17cfg47dh7hawr944f75f.ls14492026/11/11 22:22:40 WARN Found objects in DB but missing from S3, will re-upload count=114502026/11/11 22:22:40 INFO Upload complete. (116ms)14512026/11/11 22:22:40 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1452=== NAME TestClientCADerivations1453 client_ca_test.go:180: Narinfo contains CA field: StorePath: /build/TestClientCADerivations321690630/001/store/kbpb8jd670rgmy7a6x33i3v4z18lhxdc-ca-test1454 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1455 Compression: zstd1456 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1457 NarSize: 1441458 References: 1459 Deriver: /build/TestClientCADerivations321690630/001/store/z7qrgyxjf2kz3rvpsfnr8p3pmnff6c03-ca-test.drv1460 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1461 client_ca_test.go:185: Checking for realisation files in S3...1462 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1463 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache14642026/11/11 22:22:40 INFO Received complete push request method=POST path=/api/pushes/2/complete14652026/11/11 22:22:40 WARN Failed to register uploaded object key=wfz5i2hb6fv17cfg47dh7hawr944f75f.ls error="server returned 404: 404 page not found\n"14662026/11/11 22:22:40 INFO Completed push id=2 objects=3 duration=3.4861ms14672026/11/11 22:22:40 INFO Upload complete. (64ms)1468=== NAME TestClientIntegration1469 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1470 client_integration_test.go:335: Decompressed .ls content (49 bytes):1471 {"version":1,"root":{"type":"regular","size":39}}14722026/11/11 22:22:40 INFO lead: released remote=192.0.2.1:1234 generation=11473--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1474=== CONT TestGCTaskStore_GetEmpty1475--- PASS: TestGCTaskStore_GetEmpty (0.00s)1476=== CONT TestGetExistingObjectsLocksRows14772026/11/11 22:22:40 INFO lead: acquired remote=192.0.2.1:1234 generation=21478=== RUN TestService_RequireScope_OIDC/builder_may_write1479=== PAUSE TestService_RequireScope_OIDC/builder_may_write1480=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1481=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1482=== RUN TestService_RequireScope_OIDC/ops_may_admin1483=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1484=== RUN TestService_RequireScope_OIDC/ops_may_not_write1485=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1486=== RUN TestService_RequireScope_OIDC/reader_may_not_write1487=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1488=== RUN TestService_RequireScope_OIDC/static_token_may_admin1489=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1490=== RUN TestService_RequireScope_OIDC/static_token_may_write1491=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1492=== RUN TestService_RequireScope_OIDC/reader_may_read1493=== PAUSE TestService_RequireScope_OIDC/reader_may_read1494=== RUN TestService_RequireScope_OIDC/writer_implies_read1495=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1496=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1497=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1498=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1499=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1500=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1501=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1502=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1503=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1504=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1505=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1506=== CONT TestFailedS3DeleteKeepsTombstone15072026/11/11 22:22:40 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15082026/11/11 22:22:40 WARN mTLS auth: bound subjects configured but subject DN unavailable15092026/11/11 22:22:40 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1510--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (0.24s)1511=== CONT TestSweepSkipsRowsLockedByPush1512=== NAME TestNARDeduplicationMetadataUploadBug1513 metadata_upload_test.go:48: First store path: /build/TestNARDeduplicationMetadataUploadBug2423900573/001/store/xan0vbs0w5k4aabyv0wcfv56bshrjz0w-file1.txt1514--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (0.25s)1515=== CONT TestRegisterCompletedObjectNeedsPendingRow15162026/11/11 22:22:40 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1517--- PASS: TestService_AuthMiddleware (0.22s)1518=== CONT TestGCTaskStore_PhaseUpdates1519--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1520=== CONT TestReadProxyRootRedirectsToIndexHTML15212026/11/11 22:22:40 INFO Received push request method=POST path=/api/pushes15222026/11/11 22:22:40 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)15232026/11/11 22:22:40 INFO Received complete push request method=POST path=/api/pushes/3/complete15242026/11/11 22:22:40 WARN Failed to register uploaded object key=wfz5i2hb6fv17cfg47dh7hawr944f75f.ls error="server returned 404: 404 page not found\n"15252026/11/11 22:22:40 INFO Completed push id=3 objects=3 duration=3.30927ms15262026/11/11 22:22:40 INFO Upload complete. (59ms)1527=== NAME TestClientIntegration1528 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1529 client_integration_test.go:352: Decompressed .ls content (49 bytes):1530 {"version":1,"root":{"type":"regular","size":39}}1531 client_integration_test.go:363: Testing garbage collection...1532=== NAME TestClientCADerivations1533 client_ca_test.go:258: nix copy output: warning: you don't have Internet access; disabling some network-dependent features1534 warning: failed to create TLS context for AWS credential providers; SSO, STS WebIdentity, and ECS container authentication will be unavailable1535 error: binary cache 's3://bucket45?endpoint=http://localhost:38117®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/build/TestClientCADerivations321690630/001/store'1536 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 115372026/11/11 22:22:40 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket60 days=21538--- PASS: TestEnsureAbortUploadsRule (0.23s)1539=== CONT TestPush_SignsNarinfosOfItsPendingObjects1540--- PASS: TestClientCADerivations (0.76s)1541=== CONT TestReadProxyContentNegotiation15422026/11/11 22:22:40 INFO lead: released remote=192.0.2.1:1234 generation=11543--- PASS: TestLeadEndsOnShutdown (1.82s)1544=== CONT TestPush_RejectsBadRequests15452026/11/11 22:22:40 INFO Received push request method=POST path=/api/pushes15462026/11/11 22:22:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15472026/11/11 22:22:40 INFO Uploading xan0vbs0w5k4aabyv0wcfv56bshrjz0w-file1.txt (160B)15482026/11/11 22:22:40 WARN Failed to register uploaded object key=xan0vbs0w5k4aabyv0wcfv56bshrjz0w.ls error="server returned 404: 404 page not found\n"15492026/11/11 22:22:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15502026/11/11 22:22:40 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"15512026/11/11 22:22:40 INFO Signed narinfos id=1 count=115522026/11/11 22:22:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures15532026/11/11 22:22:40 INFO Uploading 1 narinfos15542026/11/11 22:22:40 INFO Garbage collection started15552026/11/11 22:22:40 INFO Received complete push request method=POST path=/api/pushes/1/complete15562026/11/11 22:22:40 WARN Failed to register uploaded object key=xan0vbs0w5k4aabyv0wcfv56bshrjz0w.narinfo error="server returned 404: 404 page not found\n"15572026/11/11 22:22:40 INFO Aborted multipart uploads count=0 kept=01558--- PASS: TestService_healthCheckHandler (0.24s)1559=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit15602026/11/11 22:22:40 INFO Completed push id=1 objects=3 duration=15.228041ms15612026/11/11 22:22:40 INFO Upload complete. (73ms)1562=== NAME TestNARDeduplicationMetadataUploadBug1563 metadata_upload_test.go:54: Retrieved narinfo from S3:1564 StorePath: /build/TestNARDeduplicationMetadataUploadBug2423900573/001/store/xan0vbs0w5k4aabyv0wcfv56bshrjz0w-file1.txt1565 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst15662026/11/11 22:22:40 WARN Force mode enabled - objects will be deleted immediately without grace period1567 Compression: zstd1568 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1569 NarSize: 1601570 References: 1571 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1572 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1573 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1574 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}15752026/11/11 22:22:41 WARN readiness check failed error="closed pool"1576--- PASS: TestService_readinessHandler (0.27s)1577=== CONT TestReadProxyConditionalGet15782026/11/11 22:22:41 INFO Aborted multipart uploads count=0 kept=015792026/11/11 22:22:41 WARN Force mode enabled - objects will be deleted immediately without grace period15802026/11/11 22:22: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=015812026/11/11 22:22:41 INFO Vacuumed table table=pending_closures15822026/11/11 22:22:41 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=015832026/11/11 22:22:41 INFO Vacuumed table table=pending_objects15842026/11/11 22:22:41 INFO Vacuumed table table=multipart_uploads1585=== NAME TestNARDeduplicationMetadataUploadBug1586 metadata_upload_test.go:64: Second store path (same content): /build/TestNARDeduplicationMetadataUploadBug2423900573/001/store/96fq26djgbjahbwsh6ikbwhsz67jdf3p-file2.txt15872026/11/11 22:22:41 INFO Vacuumed table table=closures15882026/11/11 22:22:41 INFO Received uploads request method=POST path=/api/pending_closures15892026/11/11 22:22:41 INFO Vacuumed table table=objects15902026/11/11 22:22:41 INFO Vacuumed table table=pending_closures15912026/11/11 22:22:41 INFO Vacuumed table table=pending_objects15922026/11/11 22:22:41 INFO Vacuumed table table=multipart_uploads1593--- PASS: TestCommitRacingPendingCleanupKeepsObjects (0.30s)1594=== CONT TestPush_RootsAreLockedInByteOrder15952026/11/11 22:22:41 INFO Vacuumed table table=closures15962026/11/11 22:22:41 INFO Aborted multipart uploads count=0 kept=015972026/11/11 22:22:41 INFO Vacuumed table table=objects15982026/11/11 22:22:41 WARN Force mode enabled - objects will be deleted immediately without grace period15992026/11/11 22:22: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=01600--- PASS: TestGetExistingObjectsLocksRows (0.27s)1601=== CONT TestPush_CompleteWaitsForCleanupOfThePush16022026/11/11 22:22:41 INFO Vacuumed table table=pending_closures16032026/11/11 22:22:41 INFO Vacuumed table table=pending_objects16042026/11/11 22:22:41 INFO Vacuumed table table=multipart_uploads16052026/11/11 22:22:41 INFO Vacuumed table table=closures16062026/11/11 22:22:41 INFO Received push request method=POST path=/api/pushes16072026/11/11 22:22:41 INFO Vacuumed table table=objects16082026/11/11 22:22:41 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1609--- PASS: TestSweepRechecksPendingAfterLocking (0.32s)1610=== CONT TestReadProxyOutlastsServerWriteTimeout16112026/11/11 22:22:41 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16122026/11/11 22:22:41 WARN Failed to register uploaded object key=96fq26djgbjahbwsh6ikbwhsz67jdf3p.ls error="server returned 404: 404 page not found\n"16132026/11/11 22:22:41 INFO Signed narinfos id=2 count=116142026/11/11 22:22:41 INFO Uploading 1 narinfos16152026/11/11 22:22:41 INFO Received uploads request method=POST path=/api/pending_closures16162026/11/11 22:22:41 INFO Received complete push request method=POST path=/api/pushes/2/complete16172026/11/11 22:22:41 WARN Failed to register uploaded object key=96fq26djgbjahbwsh6ikbwhsz67jdf3p.narinfo error="server returned 404: 404 page not found\n"16182026/11/11 22:22:41 INFO Completed push id=2 objects=3 duration=2.91127ms16192026/11/11 22:22:41 INFO Upload complete. (52ms)1620=== NAME TestNARDeduplicationMetadataUploadBug1621 metadata_upload_test.go:76: Retrieved narinfo from S3:1622 StorePath: /build/TestNARDeduplicationMetadataUploadBug2423900573/001/store/96fq26djgbjahbwsh6ikbwhsz67jdf3p-file2.txt1623 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1624 Compression: zstd1625 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1626 NarSize: 1601627 References: 1628 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1629 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1630 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1631 {"version":1,"root":{"type":"regular","size":44}}1632--- PASS: TestNARDeduplicationMetadataUploadBug (0.53s)1633=== CONT TestGCTaskStore_CompletedAllowsNewTask1634--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1635=== CONT TestReadProxyHead16362026/11/11 22:22:41 INFO lead: released remote=192.0.2.1:1234 generation=11637--- PASS: TestRegisterCompletedObjectNeedsPendingRow (0.29s)1638=== CONT TestPush_RepeatedRootCommitsOnce16392026/11/11 22:22:41 INFO Aborted multipart uploads count=0 kept=016402026/11/11 22:22:41 WARN Force mode enabled - objects will be deleted immediately without grace period16412026/11/11 22:22: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=016422026/11/11 22:22:41 INFO Vacuumed table table=pending_closures16432026/11/11 22:22:41 INFO Vacuumed table table=pending_objects16442026/11/11 22:22:41 INFO Vacuumed table table=multipart_uploads16452026/11/11 22:22:41 INFO Vacuumed table table=closures1646--- PASS: TestDeleteClosuresRacingPins (1.56s)1647=== CONT TestReadProxyRangeRequest16482026/11/11 22:22:41 INFO Vacuumed table table=objects16492026/11/11 22:22:41 INFO Aborted multipart uploads count=0 kept=016502026/11/11 22:22:41 WARN Force mode enabled - objects will be deleted immediately without grace period1651--- PASS: TestReadProxyRootRedirectsToIndexHTML (0.29s)1652=== CONT TestReadRedirectKeepsNarinfoProxied16532026/11/11 22:22:41 INFO lead: acquired remote=192.0.2.1:1234 generation=216542026/11/11 22:22:41 INFO Aborted multipart uploads count=0 kept=016552026/11/11 22:22:41 WARN Force mode enabled - objects will be deleted immediately without grace period16562026/11/11 22:22:41 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=016572026/11/11 22:22:41 INFO Vacuumed table table=pending_closures16582026/11/11 22:22:41 INFO Vacuumed table table=pending_objects16592026/11/11 22:22:41 INFO Vacuumed table table=multipart_uploads16602026/11/11 22:22:41 INFO Vacuumed table table=closures16612026/11/11 22:22:41 INFO Vacuumed table table=objects16622026/11/11 22:22:41 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."16632026/11/11 22:22:41 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."16642026/11/11 22:22:41 INFO lead: given back to the incumbent remote=192.0.2.1:1234 generation=21665--- PASS: TestSweepSkipsRowsLockedByPush (0.39s)1666=== CONT TestReadProxyInvalidPath16672026/11/11 22:22:41 INFO Received push request method=POST path=/api/pushes1668--- PASS: TestFailedS3DeleteKeepsTombstone (0.41s)1669=== CONT TestReadRedirectNar16702026/11/11 22:22:41 INFO lead: acquired remote=192.0.2.1:1234 generation=316712026/11/11 22:22:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16722026/11/11 22:22:41 INFO Signed narinfos id=1 count=116732026/11/11 22:22:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16742026/11/11 22:22:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16752026/11/11 22:22:41 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"16762026/11/11 22:22:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16772026/11/11 22:22:41 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"16782026/11/11 22:22:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16792026/11/11 22:22:41 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=116802026/11/11 22:22:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16812026/11/11 22:22:41 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1682--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (0.32s)1683=== CONT TestPush_CompleteCommitsEveryRoot1684=== RUN TestPush_RejectsBadRequests/no_roots1685=== PAUSE TestPush_RejectsBadRequests/no_roots1686=== RUN TestPush_RejectsBadRequests/no_objects1687=== PAUSE TestPush_RejectsBadRequests/no_objects1688=== RUN TestPush_RejectsBadRequests/bad_root1689=== PAUSE TestPush_RejectsBadRequests/bad_root1690=== RUN TestPush_RejectsBadRequests/root_not_in_objects1691=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1692=== CONT TestReadProxy4041693--- PASS: TestReadProxyContentNegotiation (0.33s)1694=== CONT TestPush_OverlappingRootsStoreOneRowPerKey16952026/11/11 22:22:41 INFO Received push request method=POST path=/api/pushes16962026/11/11 22:22:41 INFO Received complete push request method=POST path=/api/pushes/1/complete16972026/11/11 22:22:41 INFO lead: released remote=192.0.2.1:1234 generation=116982026/11/11 22:22:41 INFO Completed push id=1 objects=4 duration=11.17712ms16992026/11/11 22:22:41 INFO Received push request method=POST path=/api/pushes1700--- PASS: TestReadProxyConditionalGet (0.33s)1701=== CONT TestReadRedirectUsesPublicS3URL17022026/11/11 22:22:41 INFO Received push request method=POST path=/api/pushes17032026/11/11 22:22:41 INFO lead: acquired remote=192.0.2.1:1234 generation=217042026/11/11 22:22:41 INFO Received push request method=POST path=/api/pushes17052026/11/11 22:22:41 INFO Aborted multipart uploads count=0 kept=017062026-11-11 22:22:41.411 UTC [2056] ERROR: could not obtain lock on row in relation "closures"17072026-11-11 22:22:41.411 UTC [2056] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17082026-11-11 22:22:41.412 UTC [2056] ERROR: could not obtain lock on row in relation "closures"17092026-11-11 22:22:41.412 UTC [2056] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17102026-11-11 22:22:41.412 UTC [2056] ERROR: could not obtain lock on row in relation "closures"17112026-11-11 22:22:41.412 UTC [2056] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17122026-11-11 22:22:41.412 UTC [2056] ERROR: could not obtain lock on row in relation "closures"17132026-11-11 22:22:41.412 UTC [2056] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT17142026/11/11 22:22:41 WARN Force mode enabled - objects will be deleted immediately without grace period17152026-11-11 22:22:41.413 UTC [2056] ERROR: could not obtain lock on row in relation "closures"17162026-11-11 22:22:41.413 UTC [2056] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1717--- PASS: TestPush_RootsAreLockedInByteOrder (0.36s)1718=== CONT TestIsValidCachePath1719=== RUN TestIsValidCachePath/narinfo1720=== PAUSE TestIsValidCachePath/narinfo1721=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1722=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1723=== RUN TestIsValidCachePath/nar_zst1724=== PAUSE TestIsValidCachePath/nar_zst1725=== RUN TestIsValidCachePath/nar_xz1726=== PAUSE TestIsValidCachePath/nar_xz1727=== RUN TestIsValidCachePath/nar_bz21728=== PAUSE TestIsValidCachePath/nar_bz21729=== RUN TestIsValidCachePath/nar_uncompressed1730=== PAUSE TestIsValidCachePath/nar_uncompressed1731=== RUN TestIsValidCachePath/ls1732=== PAUSE TestIsValidCachePath/ls1733=== RUN TestIsValidCachePath/log1734=== PAUSE TestIsValidCachePath/log1735=== RUN TestIsValidCachePath/realisation1736=== PAUSE TestIsValidCachePath/realisation1737=== RUN TestIsValidCachePath/nix-cache-info1738=== PAUSE TestIsValidCachePath/nix-cache-info1739=== RUN TestIsValidCachePath/index.html1740=== PAUSE TestIsValidCachePath/index.html1741=== RUN TestIsValidCachePath/traversal_parent1742=== PAUSE TestIsValidCachePath/traversal_parent1743=== RUN TestIsValidCachePath/traversal_in_middle1744=== PAUSE TestIsValidCachePath/traversal_in_middle1745=== RUN TestIsValidCachePath/invalid_char_e1746=== PAUSE TestIsValidCachePath/invalid_char_e1747=== RUN TestIsValidCachePath/invalid_char_u1748=== PAUSE TestIsValidCachePath/invalid_char_u1749=== RUN TestIsValidCachePath/random_path1750=== PAUSE TestIsValidCachePath/random_path1751=== RUN TestIsValidCachePath/empty1752=== PAUSE TestIsValidCachePath/empty1753=== RUN TestIsValidCachePath/leading_slash1754=== PAUSE TestIsValidCachePath/leading_slash1755=== RUN TestIsValidCachePath/wrong_extension1756=== PAUSE TestIsValidCachePath/wrong_extension1757=== RUN TestIsValidCachePath/short_hash1758=== PAUSE TestIsValidCachePath/short_hash1759=== CONT TestReadProxyNarStreaming17602026/11/11 22:22:41 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=017612026/11/11 22:22:41 INFO Vacuumed table table=pending_closures17622026/11/11 22:22:41 INFO Vacuumed table table=pending_objects17632026/11/11 22:22:41 INFO Vacuumed table table=multipart_uploads17642026/11/11 22:22:41 INFO Vacuumed table table=closures17652026/11/11 22:22:41 INFO Vacuumed table table=objects17662026/11/11 22:22:41 INFO Received complete push request method=POST path=/api/pushes/2/complete17672026/11/11 22:22:41 INFO Completed push id=2 objects=4 duration=2.9276ms1768--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (0.47s)1769=== CONT TestReadProxyNarinfoAlreadyDecompressed1770--- PASS: TestReadProxyHead (0.34s)1771=== CONT TestReadProxyNarinfo17722026/11/11 22:22:41 INFO Received push request method=POST path=/api/pushes17732026/11/11 22:22:41 INFO Received complete push request method=POST path=/api/pushes/1/complete17742026/11/11 22:22:41 INFO Completed push id=1 objects=4 duration=8.55725ms1775--- PASS: TestPush_RepeatedRootCommitsOnce (0.35s)1776=== CONT TestPresentNotReportedWhileGCDeletesClosure1777=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1778=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1779=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1780=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1781=== CONT TestParseSingleRange1782=== RUN TestParseSingleRange/none1783=== PAUSE TestParseSingleRange/none1784=== RUN TestParseSingleRange/unknown_unit1785=== PAUSE TestParseSingleRange/unknown_unit1786=== RUN TestParseSingleRange/multi-range_ignored1787=== PAUSE TestParseSingleRange/multi-range_ignored1788=== RUN TestParseSingleRange/malformed_no_dash1789=== PAUSE TestParseSingleRange/malformed_no_dash1790=== RUN TestParseSingleRange/malformed_both_empty1791=== PAUSE TestParseSingleRange/malformed_both_empty1792=== RUN TestParseSingleRange/malformed_end_before_start1793=== PAUSE TestParseSingleRange/malformed_end_before_start1794=== RUN TestParseSingleRange/closed1795=== PAUSE TestParseSingleRange/closed1796=== RUN TestParseSingleRange/open-ended1797=== PAUSE TestParseSingleRange/open-ended1798=== RUN TestParseSingleRange/end_clamped_to_size1799=== PAUSE TestParseSingleRange/end_clamped_to_size1800=== RUN TestParseSingleRange/suffix1801=== PAUSE TestParseSingleRange/suffix1802=== RUN TestParseSingleRange/suffix_exceeds_size1803=== PAUSE TestParseSingleRange/suffix_exceeds_size1804=== RUN TestParseSingleRange/single_byte1805=== PAUSE TestParseSingleRange/single_byte1806=== RUN TestParseSingleRange/start_past_EOF1807=== PAUSE TestParseSingleRange/start_past_EOF1808=== RUN TestParseSingleRange/start_far_past_EOF1809=== PAUSE TestParseSingleRange/start_far_past_EOF1810=== CONT TestReadProxyDisabled1811--- PASS: TestReadProxyRangeRequest (0.35s)1812=== CONT TestPresentRefreshesOnlyStaleClosures1813--- PASS: TestPushWaitsForSweepHoldingRow (0.80s)1814=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18152026/11/11 22:22:41 INFO Received uploads request method=POST path=/1816=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key18172026/11/11 22:22:41 INFO Received request for more parts method=POST path=/1818=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key18192026/11/11 22:22:41 INFO Received complete multipart upload request method=POST path=/1820=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal18212026/11/11 22:22:41 INFO Received uploads request method=POST path=/1822--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1823 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1824 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1825 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1826 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1827=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1828--- PASS: TestReadRedirectKeepsNarinfoProxied (0.36s)1829=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18302026/11/11 22:22:41 INFO Received push request method=POST path=/api/pushes18312026/11/11 22:22:41 INFO Received complete push request method=POST path=/api/pushes/1/complete18322026/11/11 22:22:41 INFO Completed push id=1 objects=6 duration=7.16659ms1833--- PASS: TestPush_CompleteCommitsEveryRoot (0.35s)1834=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1835--- PASS: TestReadProxyInvalidPath (0.38s)1836=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1837--- PASS: TestReadRedirectNar (0.42s)1838=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed18392026-11-11 22:22:41.708 UTC [2059] ERROR: Push does not exist: id=118402026-11-11 22:22:41.708 UTC [2059] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE18412026-11-11 22:22:41.708 UTC [2059] STATEMENT: SELECT commit_push($1)1842--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (0.62s)1843=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost18442026/11/11 22:22:41 INFO Received push request method=POST path=/api/pushes1845--- PASS: TestReadProxy404 (0.50s)1846=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1847--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.51s)1848=== CONT TestPendingClosureWriteTimeout/empty1849=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1850--- PASS: TestReadRedirectUsesPublicS3URL (0.46s)1851=== CONT TestPendingClosureWriteTimeout/670k_objects1852=== CONT TestPendingClosureWriteTimeout/400_objects1853=== CONT TestProxyWriteTimeout/narinfo1854=== CONT TestProxyWriteTimeout/unknown_size1855=== CONT TestProxyWriteTimeout/1_GiB_nar1856=== CONT TestProxyWriteTimeout/10_GiB_nar1857--- PASS: TestProxyWriteTimeout (0.09s)1858 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1859 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1860 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1861 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1862=== CONT TestIsValidUploadKey/narinfo1863=== CONT TestIsValidUploadKey/realisation_plus_in_output1864=== CONT TestIsValidUploadKey/unknown_type1865=== CONT TestIsValidUploadKey/empty_key1866=== CONT TestIsValidUploadKey/absolute1867=== CONT TestIsValidUploadKey/traversal_nar1868=== CONT TestIsValidUploadKey/traversal1869=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1870=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1871=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1872=== CONT TestIsValidUploadKey/index.html1873=== CONT TestIsValidUploadKey/nix-cache-info1874=== CONT TestIsValidUploadKey/nar_plain1875=== CONT TestIsValidUploadKey/build_log1876=== CONT TestIsValidUploadKey/listing1877=== CONT TestIsValidUploadKey/build_log_equals1878=== CONT TestIsValidUploadKey/realisation1879=== CONT TestIsValidUploadKey/build_log_question_mark1880=== CONT TestIsValidUploadKey/build_log_plus_in_name1881=== CONT TestIsValidUploadKey/nar_xz1882=== CONT TestIsValidUploadKey/nar_zst1883=== CONT TestIsValidUploadKey/build_log_home-manager_file1884--- PASS: TestIsValidUploadKey (0.09s)1885 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1886 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1887 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1888 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1889 --- PASS: TestIsValidUploadKey/absolute (0.00s)1890 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1891 --- PASS: TestIsValidUploadKey/traversal (0.00s)1892 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1893 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1894 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1895 --- PASS: TestIsValidUploadKey/index.html (0.00s)1896 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1897 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1898 --- PASS: TestIsValidUploadKey/build_log (0.00s)1899 --- PASS: TestIsValidUploadKey/listing (0.00s)1900 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1901 --- PASS: TestIsValidUploadKey/realisation (0.00s)1902 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1903 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1904 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1905 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1906 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1907=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19082026/11/11 22:22:41 INFO Received uploads request method=POST path=/1909--- PASS: TestReadProxyNarStreaming (0.40s)1910=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19112026/11/11 22:22:41 INFO Received request for more parts method=POST path=/1912--- PASS: TestReadProxyNarinfoAlreadyDecompressed (0.40s)1913=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19142026/11/11 22:22:41 INFO Received complete multipart upload request method=POST path=/1915=== CONT TestResolveDBConnectionString/flag_wins1916=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1917=== CONT TestResolveDBConnectionString/nothing_configured1918=== CONT TestResolveDBConnectionString/missing_file_is_an_error1919=== CONT TestResolveDBConnectionString/file_when_flag_empty1920=== CONT TestClientErrorHandling/InvalidStorePath1921--- PASS: TestResolveDBConnectionString (0.00s)1922 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1923 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1924 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1925 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1926 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1927--- PASS: TestReadProxyDisabled (0.39s)1928=== CONT TestClientErrorHandling/ServerNotAvailable1929=== CONT TestClientErrorHandling/InvalidAuthToken19302026/11/11 22:22:41 INFO lead: released remote=192.0.2.1:1234 generation=219312026/11/11 22:22:41 INFO lead: acquired remote=192.0.2.1:1234 generation=319322026/11/11 22:22:41 INFO lead: released remote=192.0.2.1:1234 generation=31933--- PASS: TestLeadGenerationGrowsWithEveryGrant (2.86s)1934=== CONT TestCacheConfigHandler/full_config,_no_issuer1935=== CONT TestCacheConfigHandler/no_signing_keys1936=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1937=== CONT TestCacheConfigHandler/no_cache_url_configured1938--- PASS: TestCacheConfigHandler (0.00s)1939 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1940 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1941 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1942 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1943=== CONT TestServerTLSConfig/no_client_CA1944=== CONT TestServerTLSConfig/not_a_PEM_file1945--- PASS: TestPresentRefreshesOnlyStaleClosures (0.46s)1946=== CONT TestServerTLSConfig/missing_CA_file1947--- PASS: TestServerTLSConfig (0.00s)1948 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1949 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.00s)1950 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1951=== CONT TestGCEndsOnShutdown/before_the_run1952=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19532026/11/11 22:22:42 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/present19542026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures19552026/11/11 22:22:42 INFO Aborted multipart uploads count=0 kept=019562026/11/11 22:22:42 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1957--- PASS: TestReadProxyNarinfo (0.57s)1958=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19592026/11/11 22:22:42 WARN Force mode enabled - objects will be deleted immediately without grace period19602026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures19612026/11/11 22:22:42 INFO Aborted multipart uploads count=0 kept=019622026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures19632026/11/11 22:22:42 WARN Force mode enabled - objects will be deleted immediately without grace period19642026/11/11 22:22: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=019652026/11/11 22:22:42 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=019662026/11/11 22:22:42 INFO Vacuumed table table=pending_closures19672026/11/11 22:22:42 INFO Vacuumed table table=pending_closures19682026/11/11 22:22:42 INFO Vacuumed table table=pending_objects19692026/11/11 22:22:42 INFO Vacuumed table table=multipart_uploads19702026/11/11 22:22:42 INFO Vacuumed table table=closures19712026/11/11 22:22:42 INFO Vacuumed table table=pending_objects19722026/11/11 22:22:42 INFO Vacuumed table table=multipart_uploads19732026/11/11 22:22:42 INFO Vacuumed table table=closures19742026/11/11 22:22:42 INFO Vacuumed table table=objects19752026/11/11 22:22:42 INFO Vacuumed table table=objects1976=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token19772026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures1978=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected19792026/11/11 22:22:42 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]1980=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1981=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected19822026/11/11 22:22:42 WARN Authentication failed token_preview=eyJhbGciOi...iP1NONOJeQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]1983=== CONT TestService_RequireScope_OIDC/builder_may_write1984--- PASS: TestService_AuthMiddleware_OIDC (0.28s)1985 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)1986 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)1987 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)1988 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)1989=== CONT TestService_RequireScope_OIDC/reader_may_read1990=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1991=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19922026/11/11 22:22:42 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]1993=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1994=== CONT TestService_RequireScope_OIDC/writer_implies_read1995--- PASS: TestForceGCDuringPushOffersSweptObject (0.09s)1996 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (0.54s)1997 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (0.56s)1998=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1999=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2000=== CONT TestService_RequireScope_OIDC/reader_may_not_write2001=== CONT TestService_RequireScope_OIDC/static_token_may_write2002=== CONT TestService_RequireScope_OIDC/static_token_may_admin2003=== CONT TestService_RequireScope_OIDC/ops_may_admin2004=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2005=== CONT TestService_RequireScope_OIDC/ops_may_not_write2006=== CONT TestPush_RejectsBadRequests/no_roots2007=== CONT TestPush_RejectsBadRequests/bad_root20082026/11/11 22:22:42 INFO Received push request method=POST path=/api/pushes20092026/11/11 22:22:42 INFO Received push request method=POST path=/api/pushes2010=== CONT TestPush_RejectsBadRequests/root_not_in_objects2011=== CONT TestPush_RejectsBadRequests/no_objects20122026/11/11 22:22:42 INFO Received push request method=POST path=/api/pushes20132026/11/11 22:22:42 INFO Received push request method=POST path=/api/pushes2014=== CONT TestIsValidCachePath/narinfo2015=== CONT TestIsValidCachePath/index.html2016=== CONT TestIsValidCachePath/wrong_extension2017=== CONT TestIsValidCachePath/leading_slash2018=== CONT TestIsValidCachePath/empty2019=== CONT TestIsValidCachePath/random_path2020=== CONT TestIsValidCachePath/invalid_char_u2021=== CONT TestIsValidCachePath/invalid_char_e2022=== CONT TestIsValidCachePath/traversal_in_middle2023=== CONT TestIsValidCachePath/traversal_parent2024=== CONT TestIsValidCachePath/short_hash2025--- PASS: TestPush_RejectsBadRequests (0.32s)2026 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2027 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2028 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2029 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2030=== CONT TestIsValidCachePath/nar_uncompressed2031=== CONT TestIsValidCachePath/realisation2032=== CONT TestIsValidCachePath/log2033=== CONT TestIsValidCachePath/ls2034=== CONT TestIsValidCachePath/nar_xz2035=== CONT TestIsValidCachePath/nar_bz22036=== CONT TestIsValidCachePath/nix-cache-info2037--- PASS: TestService_RequireScope_OIDC (0.37s)2038 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2039 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2040 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2041 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2042 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2043 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2044 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2045 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2046 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2047 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2048 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2049 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2050 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2051 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2052=== CONT TestIsValidCachePath/nar_zst2053=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars2054--- PASS: TestIsValidCachePath (0.00s)2055 --- PASS: TestIsValidCachePath/narinfo (0.00s)2056 --- PASS: TestIsValidCachePath/index.html (0.00s)2057 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)2058 --- PASS: TestIsValidCachePath/leading_slash (0.00s)2059 --- PASS: TestIsValidCachePath/empty (0.00s)2060 --- PASS: TestIsValidCachePath/random_path (0.00s)2061 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)2062 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)2063 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)2064 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)2065 --- PASS: TestIsValidCachePath/short_hash (0.00s)2066 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)2067 --- PASS: TestIsValidCachePath/realisation (0.00s)2068 --- PASS: TestIsValidCachePath/log (0.00s)2069 --- PASS: TestIsValidCachePath/ls (0.00s)2070 --- PASS: TestIsValidCachePath/nar_xz (0.00s)2071 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)2072 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)2073 --- PASS: TestIsValidCachePath/nar_zst (0.00s)2074 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)2075=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale2076=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh20772026/11/11 22:22:42 WARN Request failed, retrying attempt=2 backoff=199.930481ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20782026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures20792026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures20802026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures20812026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures20822026/11/11 22:22:42 WARN Request failed, retrying attempt=3 backoff=376.754579ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2083=== CONT TestParseSingleRange/none2084=== CONT TestParseSingleRange/open-ended2085=== CONT TestParseSingleRange/start_far_past_EOF2086=== CONT TestParseSingleRange/start_past_EOF2087=== CONT TestParseSingleRange/single_byte2088=== CONT TestParseSingleRange/suffix_exceeds_size2089=== CONT TestParseSingleRange/suffix2090=== CONT TestParseSingleRange/end_clamped_to_size2091=== CONT TestParseSingleRange/multi-range_ignored2092=== CONT TestParseSingleRange/malformed_no_dash2093=== CONT TestParseSingleRange/unknown_unit2094=== CONT TestParseSingleRange/malformed_both_empty2095=== CONT TestParseSingleRange/closed2096=== CONT TestParseSingleRange/malformed_end_before_start2097--- PASS: TestParseSingleRange (0.00s)2098 --- PASS: TestParseSingleRange/none (0.00s)2099 --- PASS: TestParseSingleRange/open-ended (0.00s)2100 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)2101 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)2102 --- PASS: TestParseSingleRange/single_byte (0.00s)2103 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)2104 --- PASS: TestParseSingleRange/suffix (0.00s)2105 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)2106 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)2107 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)2108 --- PASS: TestParseSingleRange/unknown_unit (0.00s)2109 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)2110 --- PASS: TestParseSingleRange/closed (0.00s)2111 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)21122026/11/11 22:22:42 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21132026/11/11 22:22:42 INFO Aborted multipart uploads count=0 kept=021142026/11/11 22:22:42 WARN Force mode enabled - objects will be deleted immediately without grace period21152026/11/11 22:22:42 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21162026/11/11 22:22:42 INFO Aborted multipart uploads count=0 kept=021172026/11/11 22:22:42 WARN Force mode enabled - objects will be deleted immediately without grace period21182026/11/11 22:22:42 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:38117/bucket106/?delete=\": context canceled"2119--- PASS: TestGCEndsOnShutdown (0.00s)2120 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (0.37s)2121 --- PASS: TestGCEndsOnShutdown/before_the_run (0.38s)2122 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (0.38s)21232026/11/11 22:22:42 INFO lead: released remote=192.0.2.1:1234 generation=22124--- PASS: TestLeadElectsOneAndHandsOver (3.00s)2125=== NAME TestOrphanedObjectsGCStressTest2126 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2127 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion21282026/11/11 22:22:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2129--- PASS: TestUploadHandlersRejectOversizedBody (0.17s)2130 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.06s)2131 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)2132 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.75s)21332026/11/11 22:22:42 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLmRhNjVmMWQ2LTcyNTItNDMxNy05Y2EyLWZmMTBmN2MyNmQ2YXgxNzk0NDM1NzYyMDg2MzY1MTcy parts=1021342026/11/11 22:22:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21352026/11/11 22:22:42 INFO Completed upload id=1 objects=3 duration=2.515ms21362026/11/11 22:22:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021372026/11/11 22:22:42 INFO Received create pin request method=POST path=/api/pins/myapp21382026/11/11 22:22:42 INFO Created/updated pin name=myapp store_path=/build/TestPinProtectsFromGC479254395/001/store/7szdnnwm4lhqfbm7zn6ai8l3wf9zrwdx-pinned-file.txt narinfo_key=7szdnnwm4lhqfbm7zn6ai8l3wf9zrwdx.narinfo21392026/11/11 22:22:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures21402026/11/11 22:22:42 INFO Garbage collection started21412026/11/11 22:22:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21422026/11/11 22:22:42 INFO Aborted multipart uploads count=0 kept=021432026/11/11 22:22:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21442026/11/11 22:22:42 WARN Force mode enabled - objects will be deleted immediately without grace period21452026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures21462026/11/11 22:22: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=021472026/11/11 22:22:42 INFO Vacuumed table table=pending_closures21482026/11/11 22:22:42 INFO Vacuumed table table=pending_objects21492026/11/11 22:22:42 INFO Vacuumed table table=multipart_uploads21502026/11/11 22:22:42 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLjcyMmQxMDVmLTFlY2EtNGZkZS04MTIzLTgyODBiY2EyODNjOHgxNzk0NDM1NzYyMTE1MjUxOTcy parts=1021512026/11/11 22:22:42 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21522026/11/11 22:22:42 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21532026/11/11 22:22:42 INFO Vacuumed table table=closures21542026/11/11 22:22:42 INFO Vacuumed table table=objects21552026/11/11 22:22:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21562026/11/11 22:22:42 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLmU5YjVjNDU4LTY0MzktNGNhYS05NDkwLTExNGYxOGM2NmFjNngxNzk0NDM1NzYyMTQyMzU4OTIy parts=1021572026/11/11 22:22:42 INFO Completed upload id=1 objects=3 duration=1.964229ms21582026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures21592026/11/11 22:22:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21602026/11/11 22:22:42 INFO Completed upload id=1 objects=3 duration=3.57987ms21612026/11/11 22:22:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21622026/11/11 22:22:42 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLjY4ZmZkNDQxLTY3MzctNDdlNi04M2VjLTU4NjM4YzFkNWZkOHgxNzk0NDM1NzYyMTc4Mjk0ODkz parts=1021632026/11/11 22:22:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21642026/11/11 22:22:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21652026/11/11 22:22:42 INFO Completed upload id=1 objects=3 duration=3.54901ms21662026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures21672026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures21682026/11/11 22:22:42 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21692026/11/11 22:22:42 WARN Found objects in DB but missing from S3, will re-upload count=121702026/11/11 22:22:42 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLjYxZTAzOWRmLTZkZTAtNDI1Zi04YjRmLTU4MmZlMjIxN2E1NngxNzk0NDM1NzYyMjA4OTQ4NDIz parts=1021712026/11/11 22:22:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21722026/11/11 22:22:42 INFO Completed upload id=1 objects=3 duration=3.29298ms21732026/11/11 22:22:42 INFO Received uploads request method=POST path=/api/pending_closures21742026/11/11 22:22:42 WARN Request failed, retrying attempt=4 backoff=847.753963ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21752026/11/11 22:22:42 WARN Rate limiter enabled after throttle name=s3-test rate=521762026/11/11 22:22:42 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."2177=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle2178 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=102179 throttle_test.go:215: Rate limiter: enabled=true, rate=5.002180--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (3.83s)2181--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2182 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (0.81s)2183 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (0.84s)21842026/11/11 22:22:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02185=== NAME TestClientIntegration2186 client_integration_test.go:370: Objects in database after GC:2187 client_integration_test.go:370: Successfully deleted all objects with GC --force2188--- PASS: TestClientIntegration (2.87s)2189--- PASS: TestPendingClosureWriteTimeout (0.09s)2190 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2191 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2192 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2193 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (1.26s)21942026/11/11 22:22:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21952026/11/11 22:22:43 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLjg0MTkwYzZiLWExZWQtNDc5Ni1hYTczLWMzMTJlYjdjNDgwYngxNzk0NDM1NzYyNjIzNzc0MDE4 parts=1021962026/11/11 22:22:43 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21972026/11/11 22:22:43 INFO Completed upload id=2 objects=3 duration=1.3104ms21982026/11/11 22:22:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21992026/11/11 22:22:43 INFO lead: released remote=192.0.2.1:1234 generation=32200--- PASS: TestLeadUnannouncedStandbyYieldsToIncumbent (3.71s)22012026/11/11 22:22:43 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=MGZiZmRkMGEtZmI0Yi00YjUyLThlZWMtZTA5NjdhYTk4YmZmLmE2Zjk3NTZkLWYxOWItNGJmMi1iZmQ1LTUxN2M1ZTQzZjY1MHgxNzk0NDM1NzYyNjY2MDE3OTM4 parts=1022022026/11/11 22:22:43 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22032026/11/11 22:22:43 INFO Completed upload id=2 objects=3 duration=1.31709ms22042026/11/11 22:22:43 INFO Received uploads request method=POST path=/api/pending_closures22052026/11/11 22:22:43 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22062026/11/11 22:22:43 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22072026/11/11 22:22:43 INFO Received uploads request method=POST path=/api/pending_closures22082026/11/11 22:22:43 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22092026/11/11 22:22:43 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2210--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.09s)2211 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (1.01s)2212 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (1.02s)2213 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (0.93s)2214 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (1.54s)2215 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (1.49s)22162026/11/11 22:22:43 WARN Request failed, retrying attempt=5 backoff=1.450669442s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2217=== NAME TestOrphanedObjectsGCStressTest2218 orphaned_objects_gc_test.go:503: Stress test completed successfully:2219 orphaned_objects_gc_test.go:504: - Active objects preserved: 202220 orphaned_objects_gc_test.go:505: - Objects deleted: 2102221 orphaned_objects_gc_test.go:506: - Total GC'd: 2102222--- PASS: TestOrphanedObjectsGCStressTest (4.06s)2223=== NAME TestPinProtectsFromGC2224 client_integration_test.go:887: Pin successfully protected closure from garbage collection2225--- PASS: TestPinProtectsFromGC (4.80s)2226--- PASS: TestConnectWaitsForAPeerMigration (5.17s)22272026/11/11 22:22:45 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-config22282026/11/11 22:22:45 WARN Request failed, retrying attempt=2 backoff=206.162837ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22292026/11/11 22:22:45 WARN Request failed, retrying attempt=3 backoff=366.721397ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2230--- PASS: TestReadProxyOutlastsServerWriteTimeout (4.54s)22312026/11/11 22:22:45 WARN Request failed, retrying attempt=4 backoff=738.347739ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22322026/11/11 22:22:46 WARN Request failed, retrying attempt=5 backoff=1.694619088s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22332026/11/11 22:22:46 INFO Aborted multipart uploads count=1 kept=022342026/11/11 22:22:46 INFO Received cleanup request method=DELETE path=/api/pending_closures22352026/11/11 22:22:46 INFO Aborted multipart uploads count=1 kept=02236--- PASS: TestPendingCleanupUsesOneCutoff (6.39s)22372026/11/11 22:22:48 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"22382026/11/11 22:22:48 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-config22392026/11/11 22:22:48 WARN Request failed, retrying attempt=2 backoff=182.983298ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22402026/11/11 22:22:48 WARN Request failed, retrying attempt=3 backoff=405.84705ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22412026/11/11 22:22:48 WARN Request failed, retrying attempt=4 backoff=874.659922ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22422026/11/11 22:22:49 WARN Request failed, retrying attempt=5 backoff=1.690117629s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22432026/11/11 22:22:51 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_closures22442026/11/11 22:22:51 WARN Request failed, retrying attempt=2 backoff=216.295086ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22452026/11/11 22:22:51 WARN Request failed, retrying attempt=3 backoff=439.385676ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22462026/11/11 22:22:52 WARN Request failed, retrying attempt=4 backoff=812.515373ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22472026/11/11 22:22:52 WARN Request failed, retrying attempt=5 backoff=1.685783879s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2248--- PASS: TestClientErrorHandling (0.00s)2249 --- PASS: TestClientErrorHandling/InvalidStorePath (0.45s)2250 --- PASS: TestClientErrorHandling/InvalidAuthToken (0.47s)2251 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.78s)2252PASS2253{"timestamp":"2026-11-11T22:22:54.687884893Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:45344","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(398)"}2254{"timestamp":"2026-11-11T22:22:54.688488193Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:44136","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(387)"}2255{"timestamp":"2026-11-11T22:22:54.688747143Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:44634","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)"}2256{"timestamp":"2026-11-11T22:22:54.688908513Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:44436","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(392)"}22572026-11-11 22:22:55.023 UTC [129] LOG: received smart shutdown request22582026-11-11 22:22:55.026 UTC [129] LOG: background worker "logical replication launcher" (PID 139) exited with exit code 122592026-11-11 22:22:55.036 UTC [134] LOG: shutting down22602026-11-11 22:22:55.037 UTC [134] LOG: checkpoint starting: shutdown immediate22612026-11-11 22:22:55.875 UTC [134] LOG: checkpoint complete: wrote 11069 buffers (67.6%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.250 s, sync=0.536 s, total=0.840 s; sync files=36843, longest=0.115 s, average=0.001 s; distance=530993 kB, estimate=530993 kB; lsn=0/21DF2340, redo lsn=0/21DF234022622026-11-11 22:22:55.936 UTC [129] LOG: database system is shut down2263Running OIDC tests...2264=== RUN TestAudienceForIssuer2265=== PAUSE TestAudienceForIssuer2266=== RUN TestGlobMatch2267=== PAUSE TestGlobMatch2268=== RUN TestValidateToken_ValidToken2269=== PAUSE TestValidateToken_ValidToken2270=== RUN TestValidateToken_WrongAudience2271=== PAUSE TestValidateToken_WrongAudience2272=== RUN TestValidateToken_Expired2273=== PAUSE TestValidateToken_Expired2274=== RUN TestValidateToken_BoundClaimsMismatch2275=== PAUSE TestValidateToken_BoundClaimsMismatch2276=== RUN TestValidateToken_BoundSubjectMismatch2277=== PAUSE TestValidateToken_BoundSubjectMismatch2278=== RUN TestValidateToken_MultipleProviders2279=== PAUSE TestValidateToken_MultipleProviders2280=== RUN TestValidateToken_NoMatchingProvider2281=== PAUSE TestValidateToken_NoMatchingProvider2282=== RUN TestValidateToken_KubernetesServiceAccount2283=== PAUSE TestValidateToken_KubernetesServiceAccount2284=== RUN TestNewValidator_KubernetesRequiresCA2285=== PAUSE TestNewValidator_KubernetesRequiresCA2286=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2287=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2288=== RUN TestPins_ReservedForMatchingRule2289=== PAUSE TestPins_ReservedForMatchingRule2290=== RUN TestPins_TopLevelShorthand2291=== PAUSE TestPins_TopLevelShorthand2292=== RUN TestPins_ConfigValidation2293=== PAUSE TestPins_ConfigValidation2294=== RUN TestScopes_LegacyProviderDefaultsToWrite2295=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2296=== RUN TestScopes_Rules2297=== PAUSE TestScopes_Rules2298=== RUN TestScopes_ConfigValidation2299=== PAUSE TestScopes_ConfigValidation2300=== CONT TestAudienceForIssuer2301=== CONT TestPins_ConfigValidation2302--- PASS: TestAudienceForIssuer (0.00s)2303=== CONT TestValidateToken_NoMatchingProvider2304=== CONT TestValidateToken_MultipleProviders2305=== CONT TestValidateToken_BoundSubjectMismatch2306=== CONT TestValidateToken_BoundClaimsMismatch2307=== CONT TestValidateToken_Expired2308--- PASS: TestPins_ConfigValidation (0.00s)2309=== CONT TestValidateToken_WrongAudience2310=== CONT TestValidateToken_ValidToken2311=== CONT TestGlobMatch2312=== RUN TestGlobMatch/foo_foo2313=== PAUSE TestGlobMatch/foo_foo2314=== RUN TestGlobMatch/foo_bar2315=== PAUSE TestGlobMatch/foo_bar2316=== CONT TestPins_TopLevelShorthand2317=== CONT TestScopes_Rules2318=== CONT TestScopes_ConfigValidation2319=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2320=== CONT TestScopes_LegacyProviderDefaultsToWrite2321=== CONT TestNewValidator_KubernetesRequiresCA2322=== CONT TestValidateToken_KubernetesServiceAccount2323=== CONT TestPins_ReservedForMatchingRule2324=== RUN TestGlobMatch/*_2325=== PAUSE TestGlobMatch/*_2326=== RUN TestGlobMatch/*_anything2327=== PAUSE TestGlobMatch/*_anything2328=== RUN TestGlobMatch/foo*_foo2329=== PAUSE TestGlobMatch/foo*_foo2330=== RUN TestGlobMatch/foo*_foobar2331=== PAUSE TestGlobMatch/foo*_foobar2332=== RUN TestGlobMatch/foo*_bar2333=== PAUSE TestGlobMatch/foo*_bar2334=== RUN TestGlobMatch/*bar_bar2335=== PAUSE TestGlobMatch/*bar_bar2336=== RUN TestGlobMatch/*bar_foobar2337=== PAUSE TestGlobMatch/*bar_foobar2338=== RUN TestGlobMatch/*bar_foo2339=== PAUSE TestGlobMatch/*bar_foo2340=== RUN TestGlobMatch/foo*bar_foobar2341=== PAUSE TestGlobMatch/foo*bar_foobar2342=== RUN TestGlobMatch/foo*bar_foo123bar2343=== PAUSE TestGlobMatch/foo*bar_foo123bar2344=== RUN TestGlobMatch/foo*bar_foobarbaz2345=== PAUSE TestGlobMatch/foo*bar_foobarbaz2346=== RUN TestGlobMatch/*/*_foo/bar2347=== PAUSE TestGlobMatch/*/*_foo/bar2348=== RUN TestGlobMatch/*/*_foo2349=== PAUSE TestGlobMatch/*/*_foo2350=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2351=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2352=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02353=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02354=== RUN TestGlobMatch/refs/*/main_refs/heads/main2355=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2356=== RUN TestGlobMatch/fo?_foo2357=== PAUSE TestGlobMatch/fo?_foo2358=== RUN TestGlobMatch/fo?_fo2359=== PAUSE TestGlobMatch/fo?_fo2360=== RUN TestGlobMatch/fo?_fooo2361=== PAUSE TestGlobMatch/fo?_fooo2362=== RUN TestGlobMatch/?oo_foo2363=== PAUSE TestGlobMatch/?oo_foo2364=== RUN TestGlobMatch/?oo_boo2365=== PAUSE TestGlobMatch/?oo_boo2366=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2367--- PASS: TestScopes_ConfigValidation (0.00s)2368=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2369=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2370=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2371=== CONT TestGlobMatch/foo_foo2372=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2373=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2374=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2375=== CONT TestGlobMatch/foo*bar_foobar2376=== CONT TestGlobMatch/*bar_foo2377=== CONT TestGlobMatch/*bar_foobar2378=== CONT TestGlobMatch/*bar_bar2379=== CONT TestGlobMatch/foo*_bar2380=== CONT TestGlobMatch/foo*_foobar2381=== CONT TestGlobMatch/foo*_foo2382=== CONT TestGlobMatch/*_anything2383=== CONT TestGlobMatch/*_2384=== CONT TestGlobMatch/foo_bar2385=== CONT TestGlobMatch/*/*_foo/bar2386=== CONT TestGlobMatch/*/*_foo2387=== CONT TestGlobMatch/foo*bar_foobarbaz2388=== CONT TestGlobMatch/?oo_boo2389=== CONT TestGlobMatch/?oo_foo2390=== CONT TestGlobMatch/fo?_fooo2391=== CONT TestGlobMatch/fo?_fo2392=== CONT TestGlobMatch/fo?_foo2393=== CONT TestGlobMatch/refs/*/main_refs/heads/main2394=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02395=== CONT TestGlobMatch/foo*bar_foo123bar2396--- PASS: TestGlobMatch (0.00s)2397 --- PASS: TestGlobMatch/foo_foo (0.00s)2398 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2399 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2400 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2401 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2402 --- PASS: TestGlobMatch/*bar_foo (0.00s)2403 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2404 --- PASS: TestGlobMatch/*bar_bar (0.00s)2405 --- PASS: TestGlobMatch/foo*_bar (0.00s)2406 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2407 --- PASS: TestGlobMatch/foo*_foo (0.00s)2408 --- PASS: TestGlobMatch/*_anything (0.00s)2409 --- PASS: TestGlobMatch/*_ (0.00s)2410 --- PASS: TestGlobMatch/foo_bar (0.00s)2411 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2412 --- PASS: TestGlobMatch/*/*_foo (0.00s)2413 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2414 --- PASS: TestGlobMatch/?oo_boo (0.00s)2415 --- PASS: TestGlobMatch/?oo_foo (0.00s)2416 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2417 --- PASS: TestGlobMatch/fo?_fo (0.00s)2418 --- PASS: TestGlobMatch/fo?_foo (0.00s)2419 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2420 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2421 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)24222026/11/11 22:22:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:43087/oidc2423--- PASS: TestValidateToken_BoundSubjectMismatch (0.02s)24242026/11/11 22:22:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37059/oidc2425--- PASS: TestValidateToken_BoundClaimsMismatch (0.04s)24262026/11/11 22:22:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:38565/oidc24272026/11/11 22:22:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:42547/oidc24282026/11/11 22:22:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:41657/oidc2429--- PASS: TestValidateToken_Expired (0.05s)24302026/11/11 22:22:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:37453/oidc2431--- PASS: TestValidateToken_ValidToken (0.05s)2432--- PASS: TestScopes_Rules (0.05s)2433--- PASS: TestPins_TopLevelShorthand (0.05s)24342026/11/11 22:22:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:44271/oidc24352026/11/11 22:22:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:45779/oidc2436--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.07s)2437--- PASS: TestValidateToken_WrongAudience (0.08s)24382026/11/11 22:22:58 http: TLS handshake error from 127.0.0.1:38808: remote error: tls: bad certificate2439--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)24402026/11/11 22:22:58 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:439252441--- PASS: TestValidateToken_KubernetesServiceAccount (0.10s)24422026/11/11 22:22:58 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:38955/oidc24432026/11/11 22:22:58 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:39841/oidc2444--- PASS: TestValidateToken_MultipleProviders (0.12s)24452026/11/11 22:22:58 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:35427/oidc2446--- PASS: TestPins_ReservedForMatchingRule (0.13s)24472026/11/11 22:22:58 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:42941/oidc2448--- PASS: TestValidateToken_NoMatchingProvider (0.15s)24492026/11/11 22:22:58 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232450--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.22s)2451PASS2452Running hook tests...2453=== RUN TestSendPathsEmpty2454=== PAUSE TestSendPathsEmpty2455=== RUN TestQueueEnqueueAndFetch2456=== PAUSE TestQueueEnqueueAndFetch2457=== RUN TestQueueDeduplication2458=== PAUSE TestQueueDeduplication2459=== RUN TestQueueRemove2460=== PAUSE TestQueueRemove2461=== RUN TestQueueFetchBatchLimit2462=== PAUSE TestQueueFetchBatchLimit2463=== RUN TestQueueRetryMovesToBack2464=== PAUSE TestQueueRetryMovesToBack2465=== RUN TestQueueFetchRemoveLifecycle2466=== PAUSE TestQueueFetchRemoveLifecycle2467=== RUN TestQueueConcurrentWriters2468=== PAUSE TestQueueConcurrentWriters2469=== RUN TestQueueRemoveLargeClosure2470=== PAUSE TestQueueRemoveLargeClosure2471=== RUN TestServerClientIntegration2472--- PASS: TestServerClientIntegration (0.00s)2473=== RUN TestServerQueueError24742026/11/11 22:22:58 ERROR Failed to queue paths error="permission denied" count=12475--- PASS: TestServerQueueError (0.00s)2476=== RUN TestGetListenerSocketActivation2477 server_test.go:218: === RUN TestGetListenerSocketActivation2478 --- PASS: TestGetListenerSocketActivation (0.00s)2479 PASS2480 2481--- PASS: TestGetListenerSocketActivation (0.01s)2482=== RUN TestServerStalledClientDoesNotBlockShutdown2483=== PAUSE TestServerStalledClientDoesNotBlockShutdown2484=== RUN TestServerBacksOffOnAcceptErrors2485=== PAUSE TestServerBacksOffOnAcceptErrors2486=== RUN TestDrainIsolatesPoisonPath2487=== PAUSE TestDrainIsolatesPoisonPath2488=== RUN TestRunNotBlockedByPoisonHead2489=== PAUSE TestRunNotBlockedByPoisonHead2490=== RUN TestDrainGivesUpWhenServerDown2491=== PAUSE TestDrainGivesUpWhenServerDown2492=== RUN TestFailedPathPrunedByLaterClosure2493=== PAUSE TestFailedPathPrunedByLaterClosure2494=== RUN TestWorkerUploadsAndRemoves2495=== PAUSE TestWorkerUploadsAndRemoves2496=== RUN TestWorkerSkipsGCdPaths2497=== PAUSE TestWorkerSkipsGCdPaths2498=== RUN TestWorkerPrunesClosureDeps2499=== PAUSE TestWorkerPrunesClosureDeps2500=== RUN TestDrainTimeout2501=== PAUSE TestDrainTimeout2502=== RUN TestWorkerRemoveFailureIsNotProgress2503=== PAUSE TestWorkerRemoveFailureIsNotProgress2504=== RUN TestWorkerKeepsPathItCannotStat2505=== PAUSE TestWorkerKeepsPathItCannotStat2506=== CONT TestSendPathsEmpty2507--- PASS: TestSendPathsEmpty (0.00s)2508=== CONT TestWorkerPrunesClosureDeps2509=== CONT TestQueueFetchRemoveLifecycle2510=== CONT TestWorkerUploadsAndRemoves2511=== CONT TestFailedPathPrunedByLaterClosure2512=== CONT TestDrainGivesUpWhenServerDown2513=== CONT TestWorkerSkipsGCdPaths2514=== CONT TestWorkerKeepsPathItCannotStat2515=== CONT TestWorkerRemoveFailureIsNotProgress2516=== CONT TestRunNotBlockedByPoisonHead2517=== CONT TestDrainTimeout2518=== CONT TestServerBacksOffOnAcceptErrors2519=== CONT TestQueueRetryMovesToBack25202026/11/11 22:22:58 ERROR Accept failed error="too many open files"2521=== CONT TestServerStalledClientDoesNotBlockShutdown2522=== CONT TestQueueEnqueueAndFetch2523=== CONT TestDrainIsolatesPoisonPath2524=== CONT TestQueueRemoveLargeClosure2525=== CONT TestQueueConcurrentWriters2526=== CONT TestQueueFetchBatchLimit2527=== CONT TestQueueRemove2528=== CONT TestQueueDeduplication25292026/11/11 22:22:58 ERROR Accept failed error="too many open files"25302026/11/11 22:22:58 INFO Uploading batch count=125312026/11/11 22:22:58 ERROR Upload failed error="upload failed" count=125322026/11/11 22:22:58 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2989994464/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2989994464/002/locked/aaa: permission denied"25332026/11/11 22:22:58 INFO Upload queue status pending=225342026/11/11 22:22:58 INFO Upload queue status pending=325352026/11/11 22:22:58 INFO Upload queue status pending=225362026/11/11 22:22:58 INFO Upload queue status pending=225372026/11/11 22:22:58 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerSkipsGCdPaths2541116474/002/nonexistent25382026/11/11 22:22:58 INFO Uploading batch count=225392026/11/11 22:22:58 INFO Uploading batch count=225402026/11/11 22:22:58 ERROR Upload failed error="upload failed" count=225412026/11/11 22:22:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1863442402/002/a2542--- PASS: TestQueueEnqueueAndFetch (0.02s)25432026/11/11 22:22:58 ERROR Accept failed error="too many open files"25442026/11/11 22:22:58 INFO Uploading batch count=125452026/11/11 22:22:58 INFO Uploading batch count=125462026/11/11 22:22:58 ERROR Upload failed error="upload failed" count=125472026/11/11 22:22:58 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2989994464/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2989994464/002/locked/aaa: permission denied"2548--- PASS: TestQueueFetchBatchLimit (0.01s)25492026/11/11 22:22:58 INFO Uploading batch count=225502026/11/11 22:22:58 INFO Uploading batch count=125512026/11/11 22:22:58 INFO Uploading batch count=42552--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25532026/11/11 22:22:58 ERROR Upload failed error="upload failed" count=425542026/11/11 22:22:58 INFO Uploading batch count=125552026/11/11 22:22:58 WARN Cannot stat store path, will retry later path=/build/TestWorkerKeepsPathItCannotStat2989994464/002/locked/aaa error="stat /build/TestWorkerKeepsPathItCannotStat2989994464/002/locked/aaa: permission denied"25562026/11/11 22:22:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1863442402/002/b2557--- PASS: TestQueueRetryMovesToBack (0.02s)25582026/11/11 22:22:58 INFO Uploading batch count=125592026/11/11 22:22:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainIsolatesPoisonPath1014353212/002/bbb25602026/11/11 22:22:58 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress3686439857/002/nonexistent25612026/11/11 22:22:58 ERROR Drain finished with paths left in queue remaining=125622026/11/11 22:22:58 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12563--- PASS: TestQueueDeduplication (0.02s)25642026/11/11 22:22:58 INFO Uploading batch count=22565--- PASS: TestQueueRemove (0.02s)25662026/11/11 22:22:58 ERROR Upload failed error="upload failed" count=225672026/11/11 22:22:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1863442402/002/c25682026/11/11 22:22:58 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress3686439857/002/nonexistent25692026/11/11 22:22:58 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125702026/11/11 22:22:58 WARN Store path no longer exists (garbage collected?), removing from queue path=/build/TestWorkerRemoveFailureIsNotProgress3686439857/002/nonexistent25712026/11/11 22:22:58 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125722026/11/11 22:22:58 ERROR Drain finished with paths left in queue remaining=125732026/11/11 22:22:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1863442402/002/d2574--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25752026/11/11 22:22:58 INFO Uploading batch count=125762026/11/11 22:22:58 INFO Uploading batch count=225772026/11/11 22:22:58 ERROR Upload failed error="upload failed" count=225782026/11/11 22:22:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1863442402/002/e25792026/11/11 22:22:58 ERROR Upload failed error="upload failed" count=12580--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2581--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)25822026/11/11 22:22:58 ERROR Upload failed, will retry later error="upload failed" path=/build/TestDrainGivesUpWhenServerDown1863442402/002/f25832026/11/11 22:22:58 INFO Uploading batch count=125842026/11/11 22:22:58 ERROR Upload failed error="upload failed" count=125852026/11/11 22:22:58 INFO Uploading batch count=125862026/11/11 22:22:58 ERROR Upload failed error="upload failed" count=125872026/11/11 22:22:58 ERROR Drain finished with paths left in queue remaining=1025882026/11/11 22:22:58 ERROR Drain finished with paths left in queue remaining=12589--- PASS: TestDrainGivesUpWhenServerDown (0.03s)2590--- PASS: TestDrainIsolatesPoisonPath (0.02s)25912026/11/11 22:22:58 ERROR Accept failed error="too many open files"2592--- PASS: TestWorkerPrunesClosureDeps (0.04s)2593--- PASS: TestWorkerUploadsAndRemoves (0.04s)2594--- PASS: TestWorkerSkipsGCdPaths (0.04s)2595--- PASS: TestQueueRemoveLargeClosure (0.06s)25962026/11/11 22:22:58 ERROR Accept failed error="too many open files"25972026/11/11 22:22:58 ERROR Accept failed error="too many open files"25982026/11/11 22:22:58 ERROR Failed to decode request error="read unix /build/hook431965157/test.sock->@: i/o timeout"25992026/11/11 22:22:58 ERROR Failed to write response error="write unix /build/hook431965157/test.sock->@: i/o timeout"2600--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26012026/11/11 22:22:58 ERROR Upload failed error="context deadline exceeded" count=226022026/11/11 22:22:58 ERROR Drain finished with paths left in queue remaining=42603--- PASS: TestDrainTimeout (0.22s)2604--- PASS: TestQueueConcurrentWriters (0.25s)26052026/11/11 22:22:58 ERROR Accept failed error="too many open files"26062026/11/11 22:22:59 ERROR Accept failed error="too many open files"2607--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26082026/11/11 22:22:59 INFO Uploading batch count=126092026/11/11 22:22:59 INFO Uploading batch count=126102026/11/11 22:22:59 INFO Uploading batch count=126112026/11/11 22:22:59 ERROR Upload failed error="upload failed" count=126122026/11/11 22:22:59 INFO Uploading batch count=126132026/11/11 22:22:59 ERROR Upload failed error="upload failed" count=126142026/11/11 22:22:59 INFO Uploading batch count=126152026/11/11 22:22:59 ERROR Upload failed error="upload failed" count=126162026/11/11 22:22:59 INFO Uploading batch count=126172026/11/11 22:22:59 ERROR Upload failed error="upload failed" count=126182026/11/11 22:22:59 ERROR Drain finished with paths left in queue remaining=12619--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2620PASS2621Running signing tests...2622=== RUN TestExternalSigner2623=== PAUSE TestExternalSigner2624=== RUN TestExternalSignerWrongPublicKey2625=== PAUSE TestExternalSignerWrongPublicKey2626=== RUN TestExternalSignerErrors2627=== PAUSE TestExternalSignerErrors2628=== RUN TestExternalSignerRestartsAfterCrash2629=== PAUSE TestExternalSignerRestartsAfterCrash2630=== RUN TestExternalSignerProgramErrorKeepsProcess2631=== PAUSE TestExternalSignerProgramErrorKeepsProcess2632=== RUN TestExternalSignerClose2633=== PAUSE TestExternalSignerClose2634=== RUN TestExternalSignerRejectsInvalidPublicKey2635=== PAUSE TestExternalSignerRejectsInvalidPublicKey2636=== RUN TestExternalSignerCancellation2637=== PAUSE TestExternalSignerCancellation2638=== RUN TestGenerateFingerprint2639=== PAUSE TestGenerateFingerprint2640=== RUN TestParseSigningKey2641=== PAUSE TestParseSigningKey2642=== RUN TestSign2643=== PAUSE TestSign2644=== RUN TestSignBatch2645=== PAUSE TestSignBatch2646=== RUN TestNilKeyPublicKey2647=== PAUSE TestNilKeyPublicKey2648=== RUN TestSignErrors2649=== PAUSE TestSignErrors2650=== CONT TestExternalSigner2651=== CONT TestExternalSignerCancellation2652=== CONT TestSignBatch2653=== CONT TestExternalSignerProgramErrorKeepsProcess2654=== CONT TestExternalSignerRejectsInvalidPublicKey2655=== RUN TestExternalSignerRejectsInvalidPublicKey/#002656=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002657=== CONT TestExternalSignerClose2658=== CONT TestExternalSignerErrors2659=== CONT TestExternalSignerRestartsAfterCrash2660=== CONT TestExternalSignerWrongPublicKey2661=== CONT TestSignErrors2662=== CONT TestParseSigningKey2663=== CONT TestSign2664=== CONT TestNilKeyPublicKey2665=== CONT TestGenerateFingerprint2666=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2667--- PASS: TestNilKeyPublicKey (0.00s)2668=== RUN TestParseSigningKey/valid_32-byte_key2669=== PAUSE TestParseSigningKey/valid_32-byte_key2670=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2671=== RUN TestGenerateFingerprint/basic_with_references2672=== PAUSE TestGenerateFingerprint/basic_with_references2673--- PASS: TestSignBatch (0.00s)2674=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2675=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2676=== RUN TestExternalSignerErrors/null2677=== RUN TestParseSigningKey/no_colon2678=== PAUSE TestParseSigningKey/no_colon2679--- PASS: TestSign (0.00s)2680=== PAUSE TestExternalSignerErrors/null2681=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2682=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2683=== RUN TestGenerateFingerprint/no_references2684=== PAUSE TestGenerateFingerprint/no_references2685=== RUN TestSignErrors/nil_key2686=== RUN TestParseSigningKey/empty_name2687=== PAUSE TestParseSigningKey/empty_name2688=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2689=== PAUSE TestSignErrors/nil_key2690=== RUN TestSignErrors/nil_narinfo2691=== PAUSE TestSignErrors/nil_narinfo2692=== RUN TestSignErrors/invalid_narinfo2693=== PAUSE TestSignErrors/invalid_narinfo2694=== RUN TestSignErrors/canceled2695=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2696=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2697=== RUN TestParseSigningKey/invalid_base642698=== PAUSE TestParseSigningKey/invalid_base642699=== RUN TestExternalSignerErrors/wrong_signatures_shape2700=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2701=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2702=== PAUSE TestSignErrors/canceled2703=== CONT TestSignErrors/nil_key2704=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2705=== CONT TestSignErrors/canceled2706=== RUN TestParseSigningKey/wrong_length2707=== RUN TestExternalSignerErrors/unrequested_key2708=== PAUSE TestExternalSignerErrors/unrequested_key2709=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2710=== CONT TestSignErrors/invalid_narinfo2711=== CONT TestSignErrors/nil_narinfo2712=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2713=== PAUSE TestParseSigningKey/wrong_length2714=== CONT TestParseSigningKey/valid_32-byte_key2715=== CONT TestParseSigningKey/wrong_length2716=== CONT TestParseSigningKey/invalid_base642717=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2718=== CONT TestExternalSignerRejectsInvalidPublicKey/#002719=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2720=== RUN TestGenerateFingerprint/invalid_nar_hash_length2721=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2722=== RUN TestExternalSignerErrors/invalid_signature_base642723=== PAUSE TestExternalSignerErrors/invalid_signature_base642724=== CONT TestParseSigningKey/no_colon2725=== CONT TestParseSigningKey/empty_name2726=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2727--- PASS: TestSignErrors (0.00s)2728 --- PASS: TestSignErrors/nil_key (0.00s)2729 --- PASS: TestSignErrors/canceled (0.00s)2730 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2731 --- PASS: TestSignErrors/nil_narinfo (0.00s)2732=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2733=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2734=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2735=== RUN TestGenerateFingerprint/invalid_store_path_prefix2736=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2737=== RUN TestExternalSignerErrors/program_error2738--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.00s)2739=== RUN TestGenerateFingerprint/invalid_reference_prefix2740=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2741=== CONT TestGenerateFingerprint/basic_with_references2742=== PAUSE TestExternalSignerErrors/program_error2743=== RUN TestExternalSignerErrors/invalid_JSON2744=== PAUSE TestExternalSignerErrors/invalid_JSON2745=== CONT TestGenerateFingerprint/invalid_nar_hash_length2746--- PASS: TestParseSigningKey (0.00s)2747 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2748 --- PASS: TestParseSigningKey/wrong_length (0.00s)2749 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2750 --- PASS: TestParseSigningKey/no_colon (0.00s)2751 --- PASS: TestParseSigningKey/empty_name (0.00s)2752 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2753--- PASS: TestExternalSignerWrongPublicKey (0.00s)2754=== CONT TestGenerateFingerprint/invalid_reference_prefix2755=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2756=== CONT TestGenerateFingerprint/invalid_store_path_prefix2757=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2758=== CONT TestGenerateFingerprint/no_references2759=== RUN TestExternalSignerErrors/wrong_id2760=== PAUSE TestExternalSignerErrors/wrong_id2761=== RUN TestExternalSignerErrors/too_few_signatures2762=== PAUSE TestExternalSignerErrors/too_few_signatures2763=== RUN TestExternalSignerErrors/exit_at_startup2764--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2765 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2766 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2767 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2768 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2769 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2770=== PAUSE TestExternalSignerErrors/exit_at_startup2771=== RUN TestExternalSignerErrors/exit_on_request2772=== PAUSE TestExternalSignerErrors/exit_on_request2773=== RUN TestExternalSignerErrors/wrong_shape2774--- PASS: TestExternalSignerClose (0.00s)2775=== PAUSE TestExternalSignerErrors/wrong_shape2776=== RUN TestExternalSignerErrors/missing_signatures2777=== PAUSE TestExternalSignerErrors/missing_signatures2778=== RUN TestExternalSignerErrors/null_signatures2779=== PAUSE TestExternalSignerErrors/null_signatures2780=== RUN TestExternalSignerErrors/wrong_signature_length2781=== PAUSE TestExternalSignerErrors/wrong_signature_length2782=== RUN TestExternalSignerErrors/missing_signature_name2783=== PAUSE TestExternalSignerErrors/missing_signature_name2784=== RUN TestExternalSignerErrors/wrong_signature_name2785=== PAUSE TestExternalSignerErrors/wrong_signature_name2786--- PASS: TestGenerateFingerprint (0.00s)2787 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2788 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2789 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2790 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2791 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2792 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2793 --- PASS: TestGenerateFingerprint/no_references (0.00s)2794=== CONT TestExternalSignerErrors/null2795=== CONT TestExternalSignerErrors/wrong_signature_name2796--- PASS: TestExternalSigner (0.01s)2797=== CONT TestExternalSignerErrors/missing_signature_name2798=== CONT TestExternalSignerErrors/wrong_signature_length2799=== CONT TestExternalSignerErrors/null_signatures2800=== CONT TestExternalSignerErrors/missing_signatures2801=== CONT TestExternalSignerErrors/wrong_shape2802=== CONT TestExternalSignerErrors/exit_on_request2803=== CONT TestExternalSignerErrors/exit_at_startup2804=== CONT TestExternalSignerErrors/too_few_signatures2805=== CONT TestExternalSignerErrors/wrong_id2806=== CONT TestExternalSignerErrors/invalid_JSON2807=== CONT TestExternalSignerErrors/unrequested_key2808=== CONT TestExternalSignerErrors/wrong_signatures_shape2809=== CONT TestExternalSignerErrors/invalid_signature_base642810=== CONT TestExternalSignerErrors/program_error2811--- PASS: TestExternalSignerRestartsAfterCrash (0.01s)2812--- PASS: TestExternalSignerErrors (0.01s)2813 --- PASS: TestExternalSignerErrors/missing_signature_name (0.00s)2814 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.00s)2815 --- PASS: TestExternalSignerErrors/exit_on_request (0.01s)2816 --- PASS: TestExternalSignerErrors/missing_signatures (0.01s)2817 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.01s)2818 --- PASS: TestExternalSignerErrors/exit_at_startup (0.01s)2819 --- PASS: TestExternalSignerErrors/invalid_JSON (0.01s)2820 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.01s)2821 --- PASS: TestExternalSignerErrors/wrong_shape (0.01s)2822 --- PASS: TestExternalSignerErrors/too_few_signatures (0.01s)2823 --- PASS: TestExternalSignerErrors/wrong_id (0.01s)2824 --- PASS: TestExternalSignerErrors/null (0.01s)2825 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (0.01s)2826 --- PASS: TestExternalSignerErrors/null_signatures (0.01s)2827 --- PASS: TestExternalSignerErrors/program_error (0.01s)2828 --- PASS: TestExternalSignerErrors/unrequested_key (0.01s)2829--- PASS: TestExternalSignerCancellation (0.02s)2830PASS2831Running OpenBao signer tests...2832=== RUN TestSign2833=== PAUSE TestSign2834=== RUN TestSignErrors2835=== PAUSE TestSignErrors2836=== RUN TestServe2837=== PAUSE TestServe2838=== RUN TestServeRejectsGarbage2839=== PAUSE TestServeRejectsGarbage2840=== CONT TestSign2841=== CONT TestSignErrors2842=== CONT TestServeRejectsGarbage2843=== RUN TestSignErrors/http_error2844=== PAUSE TestSignErrors/http_error2845--- PASS: TestServeRejectsGarbage (0.00s)2846=== CONT TestServe2847=== RUN TestSignErrors/invalid_json2848=== PAUSE TestSignErrors/invalid_json2849=== RUN TestSignErrors/no_prefix2850=== PAUSE TestSignErrors/no_prefix2851=== RUN TestSignErrors/invalid_base642852=== PAUSE TestSignErrors/invalid_base642853=== CONT TestSignErrors/http_error2854=== CONT TestSignErrors/no_prefix2855--- PASS: TestServe (0.00s)2856=== CONT TestSignErrors/invalid_base642857=== CONT TestSignErrors/invalid_json2858--- PASS: TestSign (0.00s)2859--- PASS: TestSignErrors (0.00s)2860 --- PASS: TestSignErrors/invalid_base64 (0.00s)2861 --- PASS: TestSignErrors/http_error (0.00s)2862 --- PASS: TestSignErrors/no_prefix (0.00s)2863 --- PASS: TestSignErrors/invalid_json (0.00s)2864PASS