niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #473
· raw
1tribuchet: building on mac022Running 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.12s)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 TestSetClientTLS115=== CONT TestRetryTimeoutOutlastsMaxRetries116=== CONT TestStreamPushStopsWhenCanceled117--- PASS: TestStreamPushStopsWhenCanceled (0.00s)118=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess119=== CONT TestClientSignaturesByStorePath120--- PASS: TestClientSignaturesByStorePath (0.00s)121=== CONT TestPathInfoHashCompatibility122=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)123=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)124=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon125=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon126=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI127=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI128=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512129=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512130=== CONT TestStreamPushReportsSkippedPaths131=== CONT TestGetStorePathHash132=== RUN TestGetStorePathHash/valid_store_path133=== PAUSE TestGetStorePathHash/valid_store_path134=== RUN TestGetStorePathHash/basename_without_hyphen_should_error135=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error136=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error137=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error138=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error1392026/11/09 12:10:54 WARN Rate limiter enabled after throttle name=server-test rate=5140=== CONT TestStreamPushReportsSignatures141=== CONT TestStreamPushRequestLine142=== CONT TestStreamPushGivesUpOnDeadServer143=== CONT TestStreamPushIsolatesFailures144=== CONT TestStreamPushBatchesUnderLoad145=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false146=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false147=== CONT TestStreamPushReportsEveryPath1482026/11/09 12:10:54 ERROR Upload failed error="connection refused" count=20149=== CONT TestShellSplitErrors150=== CONT TestShellSplit151=== CONT TestDoWithRetry_FinalResponseBodyReadable1522026/11/09 12:10:54 ERROR Server seems unavailable, giving up on batch untried=171532026/11/09 12:10:54 ERROR Upload failed error=boom count=11542026/11/09 12:10:54 ERROR Upload failed error="bad path" count=3155=== CONT TestRateLimiterFeedback1562026/11/09 12:10:54 ERROR Upload failed error=boom count=11572026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:49818158=== CONT TestDoWithRetry_BodyReplayedViaGetBody159=== CONT TestEncodeNixBase32WithRealHash160=== CONT TestResolveStorePath161=== CONT TestPathInfoCACompatibility162=== CONT TestRegisterUploadedObject_OutlivesPush163=== CONT TestParsePathInfoJSONMultiplePaths164=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer165=== CONT TestParsePathInfoJSON1662026/11/09 12:10:54 WARN Rate limiter enabled after throttle name=server-test rate=51672026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:49823168=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error169--- PASS: TestStreamPushReportsSkippedPaths (0.00s)1702026/11/09 12:10:54 WARN Rate limiter backed off name=server-test rate=5171=== CONT TestConvertHashToNix32172=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true173=== CONT TestScriptTokenNoExpiryRerunsEveryCall174=== CONT TestFileTokenReadsAndCaches175=== CONT TestScriptTokenEmptyCommand176=== CONT TestFileTokenEmpty177=== CONT TestScriptTokenScriptFails178=== CONT TestFileTokenMissing179=== RUN TestRateLimiterFeedback/429_enables_limiter180=== CONT TestScriptTokenBadJSON181=== CONT TestScriptTokenEmptyToken182=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths183=== CONT TestSetClientTLSErrors184=== RUN TestPathInfoCACompatibility/null_ca_field185=== RUN TestParsePathInfoJSON/Nix_format1862026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:498181872026/11/09 12:10:54 WARN Rate limiter enabled after throttle name=server-test rate=51882026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:49827189=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true190=== CONT TestPartSizeForNAR191=== RUN TestPartSizeForNAR/zero_stays_at_minimum192=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum193=== RUN TestPartSizeForNAR/small_stays_at_minimum194--- PASS: TestStreamPushReportsEveryPath (0.00s)195=== CONT TestStaticToken196=== CONT TestScriptTokenCachesUntilRefresh197=== CONT TestUploadMultipart_PartsInParallel198=== RUN TestConvertHashToNix32/SRI_format_to_Nix32199=== CONT TestSetClientTLSDoesNotMutateDefaultTransport200=== RUN TestSetClientTLS/rejects_connection_without_client_cert201=== PAUSE TestRateLimiterFeedback/429_enables_limiter202=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths203=== CONT TestEncodeNixBase32204=== RUN TestSetClientTLSErrors/missing_cert_file205=== CONT TestDumpPathMatchesNix206=== CONT TestDumpPathWriterError2072026/11/09 12:10:54 WARN Rate limiter backed off name=server-test rate=5208=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths209=== PAUSE TestPathInfoCACompatibility/null_ca_field210=== RUN TestPathInfoCACompatibility/old_string_format_-_text2112026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:49827212=== RUN TestEncodeNixBase32/test_string_hash213=== PAUSE TestParsePathInfoJSON/Nix_format214--- PASS: TestShellSplitErrors (0.00s)215--- PASS: TestShellSplit (0.00s)216--- PASS: TestStreamPushReportsSignatures (0.00s)217--- PASS: TestStreamPushIsolatesFailures (0.00s)218--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)219=== PAUSE TestEncodeNixBase32/test_string_hash220=== PAUSE TestPartSizeForNAR/small_stays_at_minimum221--- PASS: TestEncodeNixBase32WithRealHash (0.00s)222=== CONT TestDumpPathSingleFile223=== RUN TestEncodeNixBase32/empty_input224=== PAUSE TestEncodeNixBase32/empty_input225=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum226=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum227=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts228=== CONT TestRegisterUploadedObjectReusesConnections2292026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:49818230--- PASS: TestDoServerRequestAttachesToken (0.00s)231=== RUN TestRateLimiterFeedback/503_enables_limiter232=== PAUSE TestRateLimiterFeedback/503_enables_limiter233=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter234=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter235=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter236=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter237--- PASS: TestResolveStorePath (0.00s)238--- PASS: TestScriptTokenEmptyCommand (0.00s)239--- PASS: TestRegisterUploadedObject_OutlivesPush (0.01s)240--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)241--- PASS: TestFileTokenMissing (0.01s)242--- PASS: TestFileTokenEmpty (0.01s)243--- PASS: TestScriptTokenScriptFails (0.01s)244--- PASS: TestStaticToken (0.00s)245--- PASS: TestFileTokenReadsAndCaches (0.01s)246--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.04s)247--- PASS: TestScriptTokenBadJSON (0.03s)248=== PAUSE TestSetClientTLSErrors/missing_cert_file249=== RUN TestSetClientTLSErrors/missing_key_file250=== PAUSE TestSetClientTLSErrors/missing_key_file251=== RUN TestSetClientTLSErrors/missing_ca_file252=== PAUSE TestSetClientTLSErrors/missing_ca_file253=== RUN TestSetClientTLSErrors/invalid_ca_file254=== PAUSE TestSetClientTLSErrors/invalid_ca_file255=== CONT TestFilterOversizedClosures256=== RUN TestFilterOversizedClosures/no_limit_keeps_everything257=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything258=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped259=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped260=== RUN TestFilterOversizedClosures/all_closures_skipped261=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths262=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text263=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert264=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica265=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32266=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun267=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts268=== CONT TestUploadMultipart_ReturnsAfterDroppedBody269=== RUN TestParsePathInfoJSON/Lix_format270=== CONT TestCaseHackSuffix271=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA272=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA273=== PAUSE TestFilterOversizedClosures/all_closures_skipped274=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry2752026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:49818276=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon277=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512278=== CONT TestGetStorePathHash/valid_store_path279=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error280=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error281=== CONT TestGetStorePathHash/basename_without_hyphen_should_error282=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false283=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)284=== CONT TestEncodeNixBase32/test_string_hash285=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true286=== CONT TestRateLimiterFeedback/429_enables_limiter287=== PAUSE TestParsePathInfoJSON/Lix_format288=== RUN TestPartSizeForNAR/1_TiB289=== CONT TestSetClientTLSErrors/missing_cert_file290=== RUN TestConvertHashToNix32/already_Nix32_format291=== RUN TestParsePathInfoJSON/empty_input292=== PAUSE TestConvertHashToNix32/already_Nix32_format293=== PAUSE TestParsePathInfoJSON/empty_input294=== RUN TestParsePathInfoJSON/whitespace_only295=== PAUSE TestParsePathInfoJSON/whitespace_only296=== RUN TestParsePathInfoJSON/invalid_JSON297=== PAUSE TestParsePathInfoJSON/invalid_JSON298=== RUN TestSetClientTLS/preserves_debug_logging_transport299=== PAUSE TestSetClientTLS/preserves_debug_logging_transport300=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter301--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.03s)302--- PASS: TestScriptTokenEmptyToken (0.04s)303=== CONT TestRateLimiterFeedback/503_enables_limiter304=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI305=== CONT TestSetClientTLSErrors/invalid_ca_file306=== CONT TestSetClientTLSErrors/missing_ca_file307=== CONT TestFilterOversizedClosures/no_limit_keeps_everything308=== CONT TestEncodeNixBase32/empty_input309=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths310=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths311=== PAUSE TestPartSizeForNAR/1_TiB312=== RUN TestPartSizeForNAR/5_TiB_S3_max_object313=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object314=== RUN TestPartSizeForNAR/capped_at_5_GiB315=== PAUSE TestPartSizeForNAR/capped_at_5_GiB316=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter317=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive318=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive319=== RUN TestPathInfoCACompatibility/new_structured_format_-_text320=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text321=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method322=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method323=== CONT TestFilterOversizedClosures/all_closures_skipped324=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped325=== RUN TestConvertHashToNix32/invalid_format326=== PAUSE TestConvertHashToNix32/invalid_format327=== CONT TestParsePathInfoJSON/Nix_format3282026/11/09 12:10:54 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=503292026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:498183302026/11/09 12:10:54 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=2000331=== CONT TestParsePathInfoJSON/empty_input332=== CONT TestParsePathInfoJSON/Lix_format3332026/11/09 12:10:54 WARN Rate limiter enabled after throttle name=s3-test rate=53342026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:49851335=== CONT TestSetClientTLSErrors/missing_key_file336--- PASS: TestGetStorePathHash (0.00s)337 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)338 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)339 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)340 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)341--- PASS: TestStreamPushRequestLine (0.05s)342=== CONT TestSetClientTLS/rejects_connection_without_client_cert343=== CONT TestParsePathInfoJSON/invalid_JSON344=== CONT TestPartSizeForNAR/zero_stays_at_minimum345--- PASS: TestPathInfoHashCompatibility (0.00s)346 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)347 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)348 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)349 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)350--- PASS: TestStreamPushBatchesUnderLoad (0.01s)351 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)352 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)353=== CONT TestParsePathInfoJSON/whitespace_only354=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA355=== CONT TestSetClientTLS/preserves_debug_logging_transport356--- PASS: TestEncodeNixBase32 (0.02s)357 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)358 --- PASS: TestEncodeNixBase32/empty_input (0.00s)359--- PASS: TestParsePathInfoJSONMultiplePaths (0.04s)360 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)361 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)362--- PASS: TestFilterOversizedClosures (0.00s)363 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)364 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)365 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)366=== CONT TestPartSizeForNAR/small_stays_at_minimum367=== CONT TestPartSizeForNAR/capped_at_5_GiB368=== CONT TestPartSizeForNAR/5_TiB_S3_max_object369=== CONT TestPartSizeForNAR/1_TiB370=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts371=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum372--- PASS: TestPartSizeForNAR (0.03s)373 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)374 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)375 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)376 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)377 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)378 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)379 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)380--- PASS: TestSetClientTLSErrors (0.03s)381 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)382 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)383 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)384 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)385=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method386=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive387=== CONT TestPathInfoCACompatibility/new_structured_format_-_text388=== CONT TestPathInfoCACompatibility/old_string_format_-_text389=== CONT TestConvertHashToNix32/SRI_format_to_Nix32390=== CONT TestPathInfoCACompatibility/null_ca_field391--- PASS: TestPathInfoCACompatibility (0.04s)392 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)393 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)394 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)395 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)396 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)397=== CONT TestConvertHashToNix32/invalid_format398=== CONT TestConvertHashToNix32/already_Nix32_format399--- PASS: TestConvertHashToNix32 (0.04s)400 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)401 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)402 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)403--- PASS: TestParsePathInfoJSON (0.04s)404 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)405 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)406 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)407 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)408 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)4092026/11/09 12:10:54 INFO Garbage collection started410--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s)4112026/11/09 12:10:54 WARN Rate limiter enabled after throttle name=server-test rate=54122026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:498914132026/11/09 12:10:54 WARN Rate limiter backed off name=server-test rate=54142026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:498184152026/11/09 12:10:54 INFO Garbage collection started4162026/11/09 12:10:54 WARN Rate limiter enabled after throttle name=server-test rate=54172026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:499154182026/11/09 12:10:54 WARN Rate limiter backed off name=server-test rate=5419--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.02s)420--- PASS: TestRateLimiterFeedback (0.04s)421 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)422 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.02s)423 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.02s)424 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.02s)425--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)4262026/11/09 12:10:54 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=04272026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:498184282026/11/09 12:10:54 WARN Garbage collection finished on another replica. Its statistics are not available here429--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.03s)4302026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:498184312026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:498184322026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:498184332026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:498184342026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:498184352026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:49818436--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.09s)4372026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:498184382026/11/09 12:10:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:49829/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:49829/api/uploads/complete4392026/11/09 12:10:54 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4402026/11/09 12:10:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:49829/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:49829/api/uploads/complete4412026/11/09 12:10:54 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4422026/11/09 12:10:54 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:49829/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:49829/api/uploads/complete4432026/11/09 12:10:54 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"444--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.11s)4452026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:498184462026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:498184472026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:498184482026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:49818449--- PASS: TestRegisterUploadedObjectReusesConnections (0.10s)4502026/11/09 12:10:54 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:49818451--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.14s)452--- PASS: TestDumpPathWriterError (0.13s)4532026/11/09 12:10:54 http: TLS handshake error from 127.0.0.1:49909: read tcp 127.0.0.1:49830->127.0.0.1:49909: use of closed network connection454--- PASS: TestSetClientTLS (0.05s)455 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)456 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)457 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.12s)458--- PASS: TestScriptTokenCachesUntilRefresh (0.17s)459--- PASS: TestCaseHackSuffix (0.22s)460--- PASS: TestDumpPathSingleFile (0.25s)461--- PASS: TestDumpPathMatchesNix (0.33s)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 "_tribuchetbld5".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 /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/postgres3013131929/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 /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/postgres3013131929/data -l logfile start492493/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/postgres3013131929:5432 - no response4942026-11-09 12:10:56.417 UTC [48653] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4952026-11-09 12:10:56.417 UTC [48653] LOG: listening on Unix socket "/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/postgres3013131929/.s.PGSQL.5432"4962026-11-09 12:10:56.427 UTC [48680] LOG: database system was shut down at 2026-11-09 12:10:56 UTC4972026-11-09 12:10:56.429 UTC [48653] LOG: database system is ready to accept connections498/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/postgres3013131929:5432 - accepting connections499{"timestamp":"2026-11-09T12:10:56.789081Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"a2b9510d-a76c-488c-9fb9-d5387a33a57f","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":8,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}500{"timestamp":"2026-11-09T12:10:56.897696Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"335ae666-856e-4b2a-b4ee-97ca84f13925","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}501{"timestamp":"2026-11-09T12:10:57.000777Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"98b12760-9c2b-448d-9b32-d0662c54ce48","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}502{"timestamp":"2026-11-09T12:10:57.104955Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"1c8b8222-a5b3-4e02-8673-bc8b6f76d83e","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}503=== RUN TestAbortSucceeded504=== PAUSE TestAbortSucceeded505=== RUN TestService_AuthMiddleware506=== PAUSE TestService_AuthMiddleware507=== RUN TestService_AuthMiddleware_MTLSProxyHeader508=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader509=== RUN TestService_AuthMiddleware_MTLSBoundSubjects510=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects511=== RUN TestService_ReadAuthMiddleware512=== PAUSE TestService_ReadAuthMiddleware513=== RUN TestService_AuthMiddleware_OIDC514=== PAUSE TestService_AuthMiddleware_OIDC515=== RUN TestService_RequireScope_OIDC516=== PAUSE TestService_RequireScope_OIDC517=== RUN TestService_ReadScope_PublicByDefault518=== PAUSE TestService_ReadScope_PublicByDefault519=== RUN TestCacheConfigHandler520=== PAUSE TestCacheConfigHandler521=== RUN TestCacheStatsHandler522=== PAUSE TestCacheStatsHandler523=== RUN TestClientCADerivations524=== PAUSE TestClientCADerivations525=== RUN TestClientErrorHandling526=== PAUSE TestClientErrorHandling527=== RUN TestClientIntegration528=== PAUSE TestClientIntegration529=== RUN TestClientMultipleUploads530=== PAUSE TestClientMultipleUploads531=== RUN TestClientWithDependencies532=== PAUSE TestClientWithDependencies533=== RUN TestClientSharedPathCommittedMidPush534=== PAUSE TestClientSharedPathCommittedMidPush535=== RUN TestPinProtectsFromGC536=== PAUSE TestPinProtectsFromGC537=== RUN TestClientPushesUseOnePush538=== PAUSE TestClientPushesUseOnePush539=== RUN TestClientFallsBackToClosures540=== PAUSE TestClientFallsBackToClosures541=== RUN TestDeleteClosuresRacingPins542=== PAUSE TestDeleteClosuresRacingPins543=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock544=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock545=== RUN TestResolveDBConnectionString546=== PAUSE TestResolveDBConnectionString547=== RUN TestConnectWaitsForAPeerMigration548=== PAUSE TestConnectWaitsForAPeerMigration549=== RUN TestLeadElectsOneAndHandsOver550=== PAUSE TestLeadElectsOneAndHandsOver551=== RUN TestLeadIncumbentWinsAfterRestart5522026/11/09 12:10:57 INFO lead: acquired remote=192.0.2.1:12345532026/11/09 12:10:58 INFO lead: released remote=192.0.2.1:12345542026/11/09 12:10:58 INFO lead: acquired remote=192.0.2.1:12345552026/11/09 12:10:59 INFO lead: released remote=192.0.2.1:1234556--- PASS: TestLeadIncumbentWinsAfterRestart (2.15s)557=== RUN TestLeadIncumbentAnnouncesAtOnce558=== PAUSE TestLeadIncumbentAnnouncesAtOnce559=== RUN TestLeadEndsOnShutdown560=== PAUSE TestLeadEndsOnShutdown561=== RUN TestLeadEndsWhenItsConnectionHangs5622026/11/09 12:10:59 INFO lead: acquired remote=192.0.2.1:12345632026-11-09 12:11:01.008 UTC [48744] FATAL: terminating connection due to administrator command5642026/11/09 12:11:01 INFO lead: acquired remote=192.0.2.1:12345652026/11/09 12:11:02 WARN lead: lock connection lost error="timeout: context deadline exceeded"5662026/11/09 12:11:02 INFO lead: released remote=192.0.2.1:12345672026/11/09 12:11:02 INFO lead: released remote=192.0.2.1:1234568--- PASS: TestLeadEndsWhenItsConnectionHangs (3.03s)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/09 12:11:02 INFO Starting HTTP server address=127.0.0.1:499556712026/11/09 12:11:02 INFO Starting HTTP server address=proxy.sock6722026/11/09 12:11:02 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6732026/11/09 12:11:02 INFO Shutdown signal received, draining in-flight requests timeout=10s674--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.21s)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.03s)741=== RUN TestWatchdogSkipsWhenUnhealthy7422026/11/09 12:11:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7432026/11/09 12:11:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7442026/11/09 12:11:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7452026/11/09 12:11:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/09 12:11:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/09 12:11:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7482026/11/09 12:11:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7492026/11/09 12:11:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7502026/11/09 12:11:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7512026/11/09 12:11:02 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"752--- PASS: TestWatchdogSkipsWhenUnhealthy (0.21s)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 TestParseSize778--- PASS: TestParseSize (0.00s)779=== CONT TestGCTaskStore_CompletedAllowsNewTask780--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)781=== CONT TestUploadHandlersRejectOversizedBody782=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT783=== CONT TestCompleteMultipartUnregistered784=== CONT TestService_verifyS3ReuploadsStaleNarinfo785=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed786=== CONT TestService_verifyS3Integrity787=== CONT TestService_createPendingClosureHandler788=== CONT TestAbortSucceeded789--- PASS: TestAbortSucceeded (0.00s)790=== CONT TestService_cleanupPendingClosuresHandler791=== CONT TestService_Rustfstest792=== CONT TestPendingClosureWriteTimeout793=== RUN TestPendingClosureWriteTimeout/empty794=== CONT TestUploadHandlersRejectInvalidKeys795=== PAUSE TestPendingClosureWriteTimeout/empty796=== RUN TestPendingClosureWriteTimeout/400_objects797=== PAUSE TestPendingClosureWriteTimeout/400_objects798=== RUN TestPendingClosureWriteTimeout/670k_objects799=== PAUSE TestPendingClosureWriteTimeout/670k_objects800=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info801=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info802=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle803=== CONT TestGCTaskStore_Fail804=== CONT TestProxyWriteTimeout805=== CONT TestGCTaskStore_PhaseUpdates806=== CONT TestReadProxyNarinfoAlreadyDecompressed807=== CONT TestGracefulShutdownDrainsInflight808=== CONT TestPresignedUploadRegisteredBeforeCommit809=== CONT TestReadProxyNarinfo810=== CONT TestCompletedNarNotReofferedAcrossClosures811=== CONT TestIsValidCachePath812=== CONT TestCompleteMultipartUpload_ErrorButObjectExists813=== CONT TestSharedNarBothUploadsComplete814=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed815=== CONT TestGCTaskStore_GetReturnsLatest816=== CONT TestIsValidUploadKey817=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline818=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal819--- PASS: TestGCTaskStore_Fail (0.00s)820--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)821--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)822=== CONT TestPush_SignsNarinfosOfItsPendingObjects823=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed824=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed825=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost826=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost827=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed828=== CONT TestGCTaskStore_GetEmpty829--- PASS: TestGCTaskStore_GetEmpty (0.00s)830=== CONT TestPush_RejectsBadRequests831=== RUN TestIsValidCachePath/narinfo832=== PAUSE TestIsValidCachePath/narinfo833=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars834=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars835=== RUN TestIsValidCachePath/nar_zst836=== PAUSE TestIsValidCachePath/nar_zst837=== RUN TestIsValidCachePath/nar_xz838=== PAUSE TestIsValidCachePath/nar_xz839=== RUN TestProxyWriteTimeout/narinfo840=== RUN TestIsValidCachePath/nar_bz2841=== RUN TestIsValidUploadKey/narinfo842=== PAUSE TestProxyWriteTimeout/narinfo843=== PAUSE TestIsValidUploadKey/narinfo844=== RUN TestProxyWriteTimeout/1_GiB_nar845=== PAUSE TestIsValidCachePath/nar_bz2846=== RUN TestIsValidUploadKey/nar_zst847=== RUN TestIsValidCachePath/nar_uncompressed848=== PAUSE TestIsValidCachePath/nar_uncompressed849=== RUN TestIsValidCachePath/ls850=== PAUSE TestIsValidCachePath/ls851=== RUN TestIsValidCachePath/log852=== PAUSE TestIsValidCachePath/log853=== RUN TestIsValidCachePath/realisation854=== PAUSE TestIsValidCachePath/realisation855=== RUN TestIsValidCachePath/nix-cache-info856=== PAUSE TestIsValidCachePath/nix-cache-info857=== RUN TestIsValidCachePath/index.html858=== PAUSE TestIsValidCachePath/index.html859=== RUN TestIsValidCachePath/traversal_parent860=== PAUSE TestIsValidCachePath/traversal_parent861=== RUN TestIsValidCachePath/traversal_in_middle862=== PAUSE TestIsValidCachePath/traversal_in_middle863=== RUN TestIsValidCachePath/invalid_char_e864=== PAUSE TestIsValidCachePath/invalid_char_e865=== RUN TestIsValidCachePath/invalid_char_u866=== PAUSE TestIsValidCachePath/invalid_char_u867=== RUN TestIsValidCachePath/random_path868=== PAUSE TestIsValidCachePath/random_path869=== RUN TestIsValidCachePath/empty870=== PAUSE TestIsValidCachePath/empty871=== RUN TestIsValidCachePath/leading_slash872=== PAUSE TestIsValidCachePath/leading_slash873=== RUN TestIsValidCachePath/wrong_extension874=== PAUSE TestIsValidCachePath/wrong_extension875=== RUN TestIsValidCachePath/short_hash876=== PAUSE TestIsValidCachePath/short_hash877=== CONT TestGCTaskStore_ConflictDifferentParams878--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)879=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit880=== CONT TestParseSingleRange881=== RUN TestParseSingleRange/none882=== PAUSE TestParseSingleRange/none883=== RUN TestParseSingleRange/unknown_unit884=== PAUSE TestParseSingleRange/unknown_unit885=== RUN TestParseSingleRange/multi-range_ignored886=== PAUSE TestParseSingleRange/multi-range_ignored887=== RUN TestParseSingleRange/malformed_no_dash888=== PAUSE TestParseSingleRange/malformed_no_dash889=== RUN TestParseSingleRange/malformed_both_empty890=== PAUSE TestParseSingleRange/malformed_both_empty891=== RUN TestParseSingleRange/malformed_end_before_start892=== PAUSE TestParseSingleRange/malformed_end_before_start893=== RUN TestParseSingleRange/closed894=== PAUSE TestParseSingleRange/closed895=== RUN TestParseSingleRange/open-ended896=== PAUSE TestParseSingleRange/open-ended897=== RUN TestParseSingleRange/end_clamped_to_size898=== PAUSE TestParseSingleRange/end_clamped_to_size899=== RUN TestParseSingleRange/suffix900=== PAUSE TestParseSingleRange/suffix901=== RUN TestParseSingleRange/suffix_exceeds_size902=== PAUSE TestParseSingleRange/suffix_exceeds_size903=== RUN TestParseSingleRange/single_byte904=== PAUSE TestParseSingleRange/single_byte905=== RUN TestParseSingleRange/start_past_EOF906=== PAUSE TestParseSingleRange/start_past_EOF907=== RUN TestParseSingleRange/start_far_past_EOF908=== PAUSE TestParseSingleRange/start_far_past_EOF909=== PAUSE TestIsValidUploadKey/nar_zst910=== RUN TestIsValidUploadKey/nar_xz911=== PAUSE TestIsValidUploadKey/nar_xz912=== RUN TestIsValidUploadKey/nar_plain913=== PAUSE TestIsValidUploadKey/nar_plain914=== RUN TestIsValidUploadKey/listing915=== PAUSE TestIsValidUploadKey/listing916=== RUN TestIsValidUploadKey/build_log917=== PAUSE TestIsValidUploadKey/build_log918=== RUN TestIsValidUploadKey/build_log_home-manager_file919=== PAUSE TestIsValidUploadKey/build_log_home-manager_file920=== RUN TestIsValidUploadKey/build_log_plus_in_name921=== PAUSE TestIsValidUploadKey/build_log_plus_in_name922=== RUN TestIsValidUploadKey/build_log_question_mark923=== PAUSE TestIsValidUploadKey/build_log_question_mark924=== RUN TestIsValidUploadKey/build_log_equals925=== PAUSE TestIsValidUploadKey/build_log_equals926=== RUN TestIsValidUploadKey/realisation927=== PAUSE TestIsValidUploadKey/realisation928=== RUN TestIsValidUploadKey/realisation_plus_in_output929=== PAUSE TestIsValidUploadKey/realisation_plus_in_output930=== RUN TestIsValidUploadKey/nix-cache-info931=== PAUSE TestIsValidUploadKey/nix-cache-info932=== RUN TestIsValidUploadKey/index.html933=== PAUSE TestIsValidUploadKey/index.html934=== RUN TestIsValidUploadKey/narinfo_key,_nar_type935=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type936=== RUN TestIsValidUploadKey/nar_key,_narinfo_type937=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type938=== RUN TestIsValidUploadKey/listing_key,_narinfo_type939=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type940=== RUN TestIsValidUploadKey/traversal941=== PAUSE TestIsValidUploadKey/traversal942=== RUN TestIsValidUploadKey/traversal_nar943=== PAUSE TestIsValidUploadKey/traversal_nar944=== RUN TestIsValidUploadKey/absolute945=== PAUSE TestIsValidUploadKey/absolute946=== RUN TestIsValidUploadKey/empty_key947=== PAUSE TestIsValidUploadKey/empty_key948=== RUN TestIsValidUploadKey/unknown_type949=== PAUSE TestIsValidUploadKey/unknown_type950=== CONT TestPresentNotReportedWhileGCDeletesClosure951=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale952=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale953=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh954=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh955=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed956=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed957=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed958=== CONT TestGCTaskStore_DeduplicateSameParams959--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)960=== CONT TestGCTaskStore_StartNew961--- PASS: TestGCTaskStore_StartNew (0.00s)962=== CONT TestReadProxyRootRedirectsToIndexHTML963=== CONT TestReadProxyDisabled964=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal965=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key966=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key967=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key968=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key969=== CONT TestPresentRefreshesOnlyStaleClosures970=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline971=== CONT TestPresentReportsOnlyClosureRoots972=== CONT TestGCEndsOnShutdown973=== RUN TestGCEndsOnShutdown/before_the_run974=== PAUSE TestGCEndsOnShutdown/before_the_run975=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete976=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete977=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark978=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark979=== CONT TestReadProxyConditionalGet980=== PAUSE TestProxyWriteTimeout/1_GiB_nar981=== RUN TestProxyWriteTimeout/10_GiB_nar982=== PAUSE TestProxyWriteTimeout/10_GiB_nar983=== RUN TestProxyWriteTimeout/unknown_size984=== PAUSE TestProxyWriteTimeout/unknown_size985=== CONT TestReadRedirectNar9862026/11/09 12:11:03 INFO Starting HTTP server address=127.0.0.1:499589872026/11/09 12:11:03 INFO Shutdown signal received, draining in-flight requests timeout=10s988--- PASS: TestGracefulShutdownDrainsInflight (0.16s)989=== CONT TestCommitRacingPendingCleanupKeepsObjects990=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure991=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure992=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart993=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart994=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts995=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts996=== CONT TestReadProxyOutlastsServerWriteTimeout9972026/11/09 12:11:04 INFO Received cleanup request method=DELETE path=/api/pending_closures9982026/11/09 12:11:04 INFO Aborted multipart uploads count=0 kept=09992026/11/09 12:11:04 INFO Received uploads request method=POST path=/api/pending_closures10002026/11/09 12:11:05 INFO Received cleanup request method=DELETE path=/api/pending_closures10012026/11/09 12:11:05 INFO Aborted multipart uploads count=1 kept=010022026/11/09 12:11:05 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10032026-11-09 12:11:05.327 UTC [48864] ERROR: Closure does not exist: id=110042026-11-09 12:11:05.327 UTC [48864] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10052026-11-09 12:11:05.327 UTC [48864] STATEMENT: -- name: CommitPendingClosure :one1006 SELECT commit_pending_closure($1::bigint)::bigint1007 1008--- PASS: TestService_cleanupPendingClosuresHandler (2.45s)1009=== CONT TestPush_RootsAreLockedInByteOrder10102026/11/09 12:11:05 INFO Received push request method=POST path=/api/pushes10112026/11/09 12:11:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10122026/11/09 12:11:05 INFO Signed narinfos id=1 count=110132026/11/09 12:11:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10142026/11/09 12:11:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10152026/11/09 12:11:05 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10162026/11/09 12:11:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10172026/11/09 12:11:05 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10182026/11/09 12:11:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10192026/11/09 12:11:05 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110202026/11/09 12:11:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10212026/11/09 12:11:05 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1022--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.71s)1023=== CONT TestReadProxyHead10242026/11/09 12:11:05 INFO Received uploads request method=POST path=/api/pending_closures10252026/11/09 12:11:06 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10262026/11/09 12:11:06 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1027--- PASS: TestCompleteMultipartUnregistered (3.21s)1028=== CONT TestPush_CompleteWaitsForCleanupOfThePush10292026/11/09 12:11:06 INFO Received uploads request method=POST path=/api/pending_closures1030--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (3.68s)1031=== CONT TestReadProxyInvalidPath10322026/11/09 12:11:06 INFO Received uploads request method=POST path=/api/pending_closures1033=== RUN TestPush_RejectsBadRequests/no_roots1034=== PAUSE TestPush_RejectsBadRequests/no_roots1035=== RUN TestPush_RejectsBadRequests/no_objects1036=== PAUSE TestPush_RejectsBadRequests/no_objects1037=== RUN TestPush_RejectsBadRequests/bad_root1038=== PAUSE TestPush_RejectsBadRequests/bad_root1039=== RUN TestPush_RejectsBadRequests/root_not_in_objects1040=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1041=== CONT TestCreatePin_ReservedPins10422026/11/09 12:11:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10432026/11/09 12:11:07 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLjg3YzZiMmIzLWRjYjAtNDNiYy1hY2NiLTVhOTlkN2RmZjRmNHgxNzk0MjI2MjY2ODYwMzY1MDAw10442026/11/09 12:11:07 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLjg3YzZiMmIzLWRjYjAtNDNiYy1hY2NiLTVhOTlkN2RmZjRmNHgxNzk0MjI2MjY2ODYwMzY1MDAw parts=110452026/11/09 12:11:07 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:49979/oidc1046--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (4.36s)1047=== CONT TestPush_RepeatedRootCommitsOnce10482026/11/09 12:11:07 INFO Received uploads request method=POST path=/api/pending_closures10492026/11/09 12:11:07 INFO Received uploads request method=POST path=/api/pending_closures10502026/11/09 12:11:07 INFO Received uploads request method=POST path=/api/pending_closures10512026/11/09 12:11:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10522026/11/09 12:11:07 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLjViNzUxZjRhLTAwZDUtNGEyYy05ZTQwLThhMmVkMmRkNTBlMHgxNzk0MjI2MjY1NzY1ODIyMDAw parts=1010532026/11/09 12:11:07 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10542026/11/09 12:11:07 INFO Completed upload id=1 objects=2 duration=22.910709ms10552026/11/09 12:11:07 INFO Received uploads request method=POST path=/api/pending_closures10562026/11/09 12:11:07 INFO Received uploads request method=POST path=/api/pending_closures10572026/11/09 12:11:07 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10582026/11/09 12:11:07 WARN Found objects in DB but missing from S3, will re-upload count=11059--- PASS: TestService_verifyS3Integrity (4.94s)1060=== CONT TestReadProxy40410612026/11/09 12:11:07 INFO Received uploads request method=POST path=/api/pending_closures1062--- PASS: TestService_Rustfstest (5.49s)1063=== CONT TestOrphanedObjectsGCStressTest10642026/11/09 12:11:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10652026/11/09 12:11:08 INFO Received uploads request method=POST path=/api/pending_closures10662026/11/09 12:11:08 INFO Received uploads request method=POST path=/api/pending_closures10672026/11/09 12:11:08 INFO Received push request method=POST path=/api/pushes10682026/11/09 12:11:09 INFO Received complete push request method=POST path=/api/pushes/1/complete10692026/11/09 12:11:09 INFO Completed push id=1 objects=4 duration=67.88975ms10702026/11/09 12:11:09 INFO Received push request method=POST path=/api/pushes10712026/11/09 12:11:09 INFO Aborted multipart uploads count=0 kept=010722026/11/09 12:11:09 WARN Force mode enabled - objects will be deleted immediately without grace period10732026/11/09 12:11:09 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=010742026/11/09 12:11:09 INFO Received uploads request method=POST path=/api/pending_closures10752026/11/09 12:11:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10762026/11/09 12:11:09 INFO Vacuumed table table=pending_closures10772026/11/09 12:11:09 INFO Vacuumed table table=pending_objects10782026/11/09 12:11:09 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLjU4OWQ4OTVjLWJlYzEtNDg5OC1iZTJlLTVmNzVmZjY3NDNlYXgxNzk0MjI2MjY3NjExOTE4MDAw parts=1010792026/11/09 12:11:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10802026/11/09 12:11:09 INFO Vacuumed table table=multipart_uploads10812026/11/09 12:11:09 INFO Completed upload id=1 objects=2 duration=18.107666ms10822026/11/09 12:11:09 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010832026/11/09 12:11:09 INFO Received uploads request method=POST path=/api/pending_closures10842026/11/09 12:11:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures10852026/11/09 12:11:09 INFO Vacuumed table table=closures10862026/11/09 12:11:09 INFO Vacuumed table table=objects10872026/11/09 12:11:09 INFO Aborted multipart uploads count=0 kept=010882026/11/09 12:11:09 INFO Received complete push request method=POST path=/api/pushes/2/complete10892026/11/09 12:11:09 INFO Completed push id=2 objects=4 duration=7.278875ms1090--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (6.79s)1091=== CONT TestPush_CompleteCommitsEveryRoot10922026/11/09 12:11:09 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=010932026/11/09 12:11:09 INFO Vacuumed table table=pending_closures10942026/11/09 12:11:09 INFO Vacuumed table table=pending_objects10952026/11/09 12:11:09 INFO Vacuumed table table=multipart_uploads10962026/11/09 12:11:09 INFO Vacuumed table table=closures1097--- PASS: TestPresentReportsOnlyClosureRoots (7.02s)1098=== CONT TestPushWaitsForSweepHoldingRow10992026/11/09 12:11:10 INFO Vacuumed table table=objects11002026/11/09 12:11:10 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001101--- PASS: TestService_createPendingClosureHandler (7.16s)1102=== CONT TestReadProxyNarStreaming11032026/11/09 12:11:10 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1104--- PASS: TestReadProxyNarinfo (7.74s)1105=== CONT TestOrphanedObjectsGC1106--- PASS: TestReadRedirectNar (8.03s)1107=== CONT TestPush_OverlappingRootsStoreOneRowPerKey1108--- PASS: TestReadProxyNarinfoAlreadyDecompressed (8.54s)1109=== CONT TestSweepRechecksPendingAfterLocking11102026/11/09 12:11:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11112026/11/09 12:11:11 WARN Rate limiter enabled after throttle name=s3-test rate=511122026/11/09 12:11:11 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1113=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1114 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101115 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001116--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (8.70s)1117=== CONT TestReadProxyContentNegotiation11182026/11/09 12:11:11 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLmQ0MDI1YmE4LTBjZjAtNDc4NS04OWJkLWRiYmZkMWYxOWJkMXgxNzk0MjI2MjY4NzIxNzUzMDAw parts=1211192026/11/09 12:11:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11202026/11/09 12:11:12 INFO Aborted multipart uploads count=0 kept=011212026/11/09 12:11:12 WARN Force mode enabled - objects will be deleted immediately without grace period11222026/11/09 12:11:12 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=011232026/11/09 12:11:12 INFO Vacuumed table table=pending_closures11242026/11/09 12:11:12 INFO Vacuumed table table=pending_objects11252026/11/09 12:11:12 INFO Vacuumed table table=multipart_uploads11262026/11/09 12:11:12 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLjMzYzk0NWY3LTY1ZmEtNGIyNi1iZDYwLWJkZjg3ZTE0NWRmZngxNzk0MjI2MjY5NTQyMDY4MDAw parts=1211272026/11/09 12:11:12 INFO Received uploads request method=POST path=/api/pending_closures1128--- PASS: TestCompletedNarNotReofferedAcrossClosures (9.43s)1129=== CONT TestObjectStatsUpdatedOncePerCommit11302026/11/09 12:11:12 INFO Vacuumed table table=closures11312026/11/09 12:11:12 INFO Vacuumed table table=objects1132--- PASS: TestCommitRacingPendingCleanupKeepsObjects (9.35s)1133=== CONT TestReadRedirectUsesPublicS3URL1134--- PASS: TestPresentRefreshesOnlyStaleClosures (9.79s)1135=== CONT TestGetExistingObjectsLocksRows1136--- PASS: TestReadProxyDisabled (10.08s)1137=== CONT TestObjectStatsTrigger1138--- PASS: TestReadProxyConditionalGet (10.62s)1139=== CONT TestReadProxyRangeRequest11402026/11/09 12:11:14 INFO Received uploads request method=POST path=/api/pending_closures11412026/11/09 12:11:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11422026/11/09 12:11:14 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLjc3MDJhMTExLWVmZjQtNGM4Ni1iYTFlLWE0YjZkZDBlM2Q5MHgxNzk0MjI2MjY4Nzc5NTg4MDAw parts=121143--- PASS: TestSharedNarBothUploadsComplete (11.47s)1144=== CONT TestReadRedirectKeepsNarinfoProxied11452026/11/09 12:11:14 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11462026/11/09 12:11:14 INFO Received uploads request method=POST path=/api/pending_closures1147--- PASS: TestPresignedUploadRegisteredBeforeCommit (11.54s)1148=== CONT TestRegisterCompletedObjectNeedsPendingRow1149--- PASS: TestReadProxyRootRedirectsToIndexHTML (11.75s)1150=== CONT TestPendingCleanupUsesOneCutoff11512026/11/09 12:11:14 INFO Received push request method=POST path=/api/pushes11522026-11-09 12:11:15.229 UTC [49139] ERROR: could not obtain lock on row in relation "closures"11532026-11-09 12:11:15.229 UTC [49139] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11542026-11-09 12:11:15.233 UTC [49139] ERROR: could not obtain lock on row in relation "closures"11552026-11-09 12:11:15.233 UTC [49139] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11562026-11-09 12:11:15.238 UTC [49139] ERROR: could not obtain lock on row in relation "closures"11572026-11-09 12:11:15.238 UTC [49139] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11582026-11-09 12:11:15.241 UTC [49139] ERROR: could not obtain lock on row in relation "closures"11592026-11-09 12:11:15.241 UTC [49139] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11602026-11-09 12:11:15.248 UTC [49139] ERROR: could not obtain lock on row in relation "closures"11612026-11-09 12:11:15.248 UTC [49139] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1162--- PASS: TestPush_RootsAreLockedInByteOrder (9.94s)1163=== CONT TestCreatePendingClosureRejectsOversizedNAR11642026/11/09 12:11:15 INFO Received uploads request method=POST path=/api/pending_closures1165--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1166=== CONT TestCacheConfigHandlerMaxNarSize1167--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1168=== CONT TestSweepSkipsRowsLockedByPush1169--- PASS: TestReadProxyHead (9.86s)1170=== CONT TestEnsureAbortUploadsRule11712026/11/09 12:11:15 INFO Received push request method=POST path=/api/pushes1172--- PASS: TestReadProxyInvalidPath (9.49s)1173=== CONT TestDeleteClosuresRacingPins11742026-11-09 12:11:16.194 UTC [49195] ERROR: Push does not exist: id=111752026-11-09 12:11:16.194 UTC [49195] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11762026-11-09 12:11:16.194 UTC [49195] STATEMENT: SELECT commit_push($1)1177--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (10.14s)1178=== CONT TestFailedS3DeleteKeepsTombstone11792026/11/09 12:11:16 INFO Received push request method=POST path=/api/pushes11802026/11/09 12:11:16 INFO Received complete push request method=POST path=/api/pushes/1/complete11812026/11/09 12:11:16 INFO Completed push id=1 objects=4 duration=45.596542ms1182--- PASS: TestPush_RepeatedRootCommitsOnce (9.31s)1183=== CONT TestForceGCDuringPushOffersSweptObject1184=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1185=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1186=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1187=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1188=== CONT TestNARDeduplicationMetadataUploadBug1189--- PASS: TestReadProxyOutlastsServerWriteTimeout (13.58s)1190=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection11912026/11/09 12:11:16 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11922026/11/09 12:11:16 WARN Refused reserved pin name=worker-x86_64-linux11932026/11/09 12:11:16 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11942026/11/09 12:11:16 INFO Received create pin request method=POST path=/api/pins/my-app11952026/11/09 12:11:16 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1196--- PASS: TestCreatePin_ReservedPins (9.49s)1197=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1198--- PASS: TestReadProxy404 (10.01s)1199=== CONT TestClientFallsBackToClosures12002026/11/09 12:11:17 INFO Received uploads request method=POST path=/api/pending_closures12012026/11/09 12:11:18 INFO Received push request method=POST path=/api/pushes12022026/11/09 12:11:18 INFO Received complete push request method=POST path=/api/pushes/1/complete12032026/11/09 12:11:18 INFO Completed push id=1 objects=6 duration=27.828125ms1204--- PASS: TestPush_CompleteCommitsEveryRoot (8.63s)1205=== CONT TestMultipartCleanup1206--- PASS: TestPushWaitsForSweepHoldingRow (8.43s)1207=== CONT TestServerTLSConfig1208=== RUN TestServerTLSConfig/no_client_CA1209=== PAUSE TestServerTLSConfig/no_client_CA1210=== RUN TestServerTLSConfig/missing_CA_file1211=== PAUSE TestServerTLSConfig/missing_CA_file1212=== RUN TestServerTLSConfig/not_a_PEM_file1213=== PAUSE TestServerTLSConfig/not_a_PEM_file1214=== CONT TestGenerateLandingPage1215--- PASS: TestGenerateLandingPage (0.00s)1216=== CONT TestService_NativeMTLS1217--- PASS: TestReadProxyNarStreaming (8.48s)1218=== CONT TestGCSweepDeliversEachKeyOnce12192026/11/09 12:11:19 INFO Received push request method=POST path=/api/pushes1220--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (8.21s)1221=== CONT TestService_readinessHandler12222026/11/09 12:11:19 INFO Aborted multipart uploads count=0 kept=012232026/11/09 12:11:19 WARN Force mode enabled - objects will be deleted immediately without grace period12242026/11/09 12:11:19 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=012252026/11/09 12:11:19 INFO Vacuumed table table=pending_closures12262026/11/09 12:11:19 INFO Vacuumed table table=pending_objects12272026/11/09 12:11:19 INFO Vacuumed table table=multipart_uploads12282026/11/09 12:11:19 INFO Vacuumed table table=closures12292026/11/09 12:11:19 INFO Vacuumed table table=objects1230--- PASS: TestSweepRechecksPendingAfterLocking (8.32s)1231=== CONT TestMetricsCommit1232--- PASS: TestReadProxyContentNegotiation (8.45s)1233=== CONT TestService_healthCheckHandler1234--- PASS: TestObjectStatsUpdatedOncePerCommit (8.28s)1235=== CONT TestMetricsInventory1236--- PASS: TestReadRedirectUsesPublicS3URL (8.54s)1237=== CONT TestClientPushesUseOnePush1238=== NAME TestOrphanedObjectsGC1239 orphaned_objects_gc_test.go:287: GC Test Summary:1240 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1241 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1242 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1243 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1244 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1245--- PASS: TestOrphanedObjectsGC (10.73s)1246=== CONT TestCacheStatsHandler1247--- PASS: TestGetExistingObjectsLocksRows (8.87s)1248=== CONT TestPinProtectsFromGC1249--- PASS: TestObjectStatsTrigger (8.93s)1250=== CONT TestClientSharedPathCommittedMidPush1251--- PASS: TestReadProxyRangeRequest (8.95s)1252=== CONT TestClientWithDependencies1253--- PASS: TestRegisterCompletedObjectNeedsPendingRow (8.37s)1254=== CONT TestClientMultipleUploads1255--- PASS: TestReadRedirectKeepsNarinfoProxied (8.76s)1256=== CONT TestClientIntegration12572026/11/09 12:11:23 INFO Received uploads request method=POST path=/api/pending_closures12582026/11/09 12:11:23 INFO Received uploads request method=POST path=/api/pending_closures12592026/11/09 12:11:23 INFO Received cleanup request method=DELETE path=/api/pending_closures12602026/11/09 12:11:24 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket51 days=21261--- PASS: TestEnsureAbortUploadsRule (8.63s)1262=== CONT TestClientErrorHandling1263=== RUN TestClientErrorHandling/InvalidStorePath1264=== PAUSE TestClientErrorHandling/InvalidStorePath1265=== RUN TestClientErrorHandling/InvalidAuthToken1266=== PAUSE TestClientErrorHandling/InvalidAuthToken1267=== RUN TestClientErrorHandling/ServerNotAvailable1268=== PAUSE TestClientErrorHandling/ServerNotAvailable1269=== CONT TestTombstonedObjectOfferedWithoutWaiting12702026/11/09 12:11:24 INFO Aborted multipart uploads count=0 kept=012712026/11/09 12:11:24 WARN Force mode enabled - objects will be deleted immediately without grace period12722026/11/09 12:11:24 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=012732026/11/09 12:11:24 INFO Vacuumed table table=pending_closures12742026/11/09 12:11:24 INFO Vacuumed table table=pending_objects12752026/11/09 12:11:24 INFO Vacuumed table table=multipart_uploads12762026/11/09 12:11:24 INFO Vacuumed table table=closures12772026/11/09 12:11:24 INFO Vacuumed table table=objects12782026/11/09 12:11:24 INFO Aborted multipart uploads count=0 kept=012792026/11/09 12:11:24 WARN Force mode enabled - objects will be deleted immediately without grace period12802026/11/09 12:11:24 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=012812026/11/09 12:11:24 INFO Vacuumed table table=pending_closures12822026/11/09 12:11:24 INFO Vacuumed table table=pending_objects12832026/11/09 12:11:24 INFO Vacuumed table table=multipart_uploads12842026/11/09 12:11:25 INFO Vacuumed table table=closures12852026/11/09 12:11:25 INFO Vacuumed table table=objects1286--- PASS: TestSweepSkipsRowsLockedByPush (9.76s)1287=== CONT TestClientCADerivations12882026/11/09 12:11:25 INFO Received uploads request method=POST path=/api/pending_closures12892026/11/09 12:11:25 INFO Aborted multipart uploads count=0 kept=012902026/11/09 12:11:25 WARN Force mode enabled - objects will be deleted immediately without grace period12912026/11/09 12:11:25 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."12922026/11/09 12:11:25 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1293--- PASS: TestFailedS3DeleteKeepsTombstone (9.17s)1294=== CONT TestGCSweepSkipsPendingObjects12952026/11/09 12:11:25 INFO Received uploads request method=POST path=/api/pending_closures1296=== NAME TestNARDeduplicationMetadataUploadBug1297 metadata_upload_test.go:48: First store path: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestNARDeduplicationMetadataUploadBug3840691892/001/store/j9pwkj3lff5ijzq344fbpawbq3rsxs6c-file1.txt12982026/11/09 12:11:26 INFO Received push request method=POST path=/api/pushes1299--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (9.34s)1300=== CONT TestSkippedUploadsHandler13012026/11/09 12:11:26 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001302--- PASS: TestSkippedUploadsHandler (0.00s)1303=== CONT TestDeduplicatedObjectsRecordedAsPending13042026/11/09 12:11:26 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13052026/11/09 12:11:26 INFO Uploading j9pwkj3lff5ijzq344fbpawbq3rsxs6c-file1.txt (160B)13062026/11/09 12:11:26 INFO Received uploads request method=POST path=/api/pending_closures13072026/11/09 12:11:26 WARN Failed to register uploaded object key=j9pwkj3lff5ijzq344fbpawbq3rsxs6c.ls error="server returned 404: 404 page not found\n"13082026/11/09 12:11:26 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13092026/11/09 12:11:26 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"13102026/11/09 12:11:26 INFO Signed narinfos id=1 count=113112026/11/09 12:11:26 INFO Uploading 1 narinfos13122026/11/09 12:11:26 INFO Received complete push request method=POST path=/api/pushes/1/complete13132026/11/09 12:11:26 WARN Failed to register uploaded object key=j9pwkj3lff5ijzq344fbpawbq3rsxs6c.narinfo error="server returned 404: 404 page not found\n"1314--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (9.58s)1315=== CONT TestPushDedupSurvivesConcurrentGC13162026/11/09 12:11:26 INFO Completed push id=1 objects=3 duration=58.757167ms13172026/11/09 12:11:26 INFO Upload complete. (403ms)1318=== NAME TestNARDeduplicationMetadataUploadBug1319 metadata_upload_test.go:54: Retrieved narinfo from S3:1320 StorePath: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestNARDeduplicationMetadataUploadBug3840691892/001/store/j9pwkj3lff5ijzq344fbpawbq3rsxs6c-file1.txt1321 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1322 Compression: zstd1323 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1324 NarSize: 1601325 References: 1326 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1327 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1328 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1329 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1330 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestNARDeduplicationMetadataUploadBug3840691892/001/store/m4rmqnylhs4zh5waxw2m27hpgx9c8jyl-file2.txt13312026/11/09 12:11:27 INFO Received push request method=POST path=/api/pushes13322026/11/09 12:11:27 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)13332026/11/09 12:11:27 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13342026/11/09 12:11:27 WARN Failed to register uploaded object key=m4rmqnylhs4zh5waxw2m27hpgx9c8jyl.ls error="server returned 404: 404 page not found\n"13352026/11/09 12:11:27 INFO Received uploads request method=POST path=/api/pending_closures13362026/11/09 12:11:27 INFO Signed narinfos id=2 count=113372026/11/09 12:11:27 INFO Uploading 1 narinfos13382026/11/09 12:11:27 INFO Received complete push request method=POST path=/api/pushes/2/complete13392026/11/09 12:11:27 WARN Failed to register uploaded object key=m4rmqnylhs4zh5waxw2m27hpgx9c8jyl.narinfo error="server returned 404: 404 page not found\n"13402026/11/09 12:11:27 INFO Completed push id=2 objects=3 duration=3.064916ms13412026/11/09 12:11:27 INFO Upload complete. (603ms)1342 metadata_upload_test.go:76: Retrieved narinfo from S3:1343 StorePath: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestNARDeduplicationMetadataUploadBug3840691892/001/store/m4rmqnylhs4zh5waxw2m27hpgx9c8jyl-file2.txt1344 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1345 Compression: zstd1346 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1347 NarSize: 1601348 References: 1349 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1350 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1351 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1352 {"version":1,"root":{"type":"regular","size":44}}1353--- PASS: TestNARDeduplicationMetadataUploadBug (10.82s)1354=== CONT TestLeadIncumbentAnnouncesAtOnce13552026/11/09 12:11:27 INFO Received cleanup request method=DELETE path=/api/pending_closures13562026/11/09 12:11:27 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket59/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""13572026/11/09 12:11:27 INFO Aborted multipart uploads count=0 kept=113582026/11/09 12:11:27 INFO Received cleanup request method=DELETE path=/api/pending_closures13592026/11/09 12:11:27 INFO Aborted multipart uploads count=1 kept=01360--- PASS: TestMultipartCleanup (9.35s)1361=== CONT TestLeadElectsOneAndHandsOver13622026/11/09 12:11:27 WARN mTLS auth: subject not in bound subjects subject="CN=reader"13632026/11/09 12:11:27 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1364--- PASS: TestService_NativeMTLS (9.39s)1365=== CONT TestGCMetrics13662026/11/09 12:11:27 INFO Received uploads request method=POST path=/api/pending_closures13672026/11/09 12:11:27 INFO Received uploads request method=POST path=/api/pending_closures13682026/11/09 12:11:28 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13692026/11/09 12:11:28 INFO Uploading x7vf22d5gkw4vrwxs1ah1ssr9k3qg6g8-b (256B)13702026/11/09 12:11:28 INFO Uploading 8n4jm4cychncbzy30ry6y9rffylsxqyd-shared-dep (136B)13712026/11/09 12:11:28 WARN Failed to register uploaded object key=nar/0bdpmhydlzkw0iriqddixqc72n5a8zz5k25qd2fy5phjp7dyzpd0.nar.zst error="server returned 404: 404 page not found\n"13722026/11/09 12:11:28 WARN Failed to register uploaded object key=8n4jm4cychncbzy30ry6y9rffylsxqyd.ls error="server returned 404: 404 page not found\n"13732026/11/09 12:11:28 WARN Failed to register uploaded object key=x7vf22d5gkw4vrwxs1ah1ssr9k3qg6g8.ls error="server returned 404: 404 page not found\n"13742026/11/09 12:11:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13752026/11/09 12:11:28 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13762026/11/09 12:11:28 WARN Failed to register uploaded object key=j6pzkpm72n0n9ra1pcadwawds775dcqr.ls error="server returned 404: 404 page not found\n"13772026/11/09 12:11:28 INFO Signed narinfos id=1 count=213782026/11/09 12:11:28 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13792026/11/09 12:11:28 INFO Signed narinfos id=2 count=213802026/11/09 12:11:28 INFO Uploading 4 narinfos13812026/11/09 12:11:28 WARN Failed to register uploaded object key=j6pzkpm72n0n9ra1pcadwawds775dcqr.narinfo error="server returned 404: 404 page not found\n"13822026/11/09 12:11:28 WARN Failed to register uploaded object key=x7vf22d5gkw4vrwxs1ah1ssr9k3qg6g8.narinfo error="server returned 404: 404 page not found\n"13832026/11/09 12:11:28 WARN Failed to register uploaded object key=8n4jm4cychncbzy30ry6y9rffylsxqyd.narinfo error="server returned 404: 404 page not found\n"13842026/11/09 12:11:28 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13852026/11/09 12:11:28 WARN Failed to register uploaded object key=8n4jm4cychncbzy30ry6y9rffylsxqyd.narinfo error="server returned 404: 404 page not found\n"13862026/11/09 12:11:28 INFO Completed upload id=2 objects=6 duration=19.407541ms13872026/11/09 12:11:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13882026/11/09 12:11:28 INFO Completed upload id=1 objects=6 duration=8.600875ms13892026/11/09 12:11:28 INFO Upload complete. (611ms)1390=== NAME TestClientFallsBackToClosures1391 client_pushes_test.go:112: Retrieved narinfo from S3:1392 StorePath: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientFallsBackToClosures256013957/001/store/8n4jm4cychncbzy30ry6y9rffylsxqyd-shared-dep1393 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1394 Compression: zstd1395 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821396 NarSize: 1361397 References: 1398 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1399 client_pushes_test.go:112: Retrieved narinfo from S3:1400 StorePath: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientFallsBackToClosures256013957/001/store/j6pzkpm72n0n9ra1pcadwawds775dcqr-a1401 URL: nar/0bdpmhydlzkw0iriqddixqc72n5a8zz5k25qd2fy5phjp7dyzpd0.nar.zst1402 Compression: zstd1403 NarHash: sha256:0bdpmhydlzkw0iriqddixqc72n5a8zz5k25qd2fy5phjp7dyzpd01404 NarSize: 2561405 References: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientFallsBackToClosures256013957/001/store/8n4jm4cychncbzy30ry6y9rffylsxqyd-shared-dep1406 CA: text:sha256:03h9h703nyxlgipdj2hlx3rn00cb8d6jfnvfkc23dk79vx9xd5sk1407 client_pushes_test.go:112: Retrieved narinfo from S3:1408 StorePath: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientFallsBackToClosures256013957/001/store/x7vf22d5gkw4vrwxs1ah1ssr9k3qg6g8-b1409 URL: nar/0bdpmhydlzkw0iriqddixqc72n5a8zz5k25qd2fy5phjp7dyzpd0.nar.zst1410 Compression: zstd1411 NarHash: sha256:0bdpmhydlzkw0iriqddixqc72n5a8zz5k25qd2fy5phjp7dyzpd01412 NarSize: 2561413 References: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientFallsBackToClosures256013957/001/store/8n4jm4cychncbzy30ry6y9rffylsxqyd-shared-dep1414 CA: text:sha256:03h9h703nyxlgipdj2hlx3rn00cb8d6jfnvfkc23dk79vx9xd5sk1415--- PASS: TestClientFallsBackToClosures (10.60s)1416=== CONT TestService_ReadAuthMiddleware14172026/11/09 12:11:28 INFO Aborted multipart uploads count=0 kept=014182026/11/09 12:11:28 WARN Force mode enabled - objects will be deleted immediately without grace period14192026/11/09 12:11:28 WARN readiness check failed error="closed pool"1420--- PASS: TestService_readinessHandler (9.56s)1421=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14222026/11/09 12:11:29 INFO Received push request method=POST path=/api/pushes1423--- PASS: TestDeleteClosuresRacingPins (13.31s)1424=== CONT TestGCBugBareHashReferences14252026/11/09 12:11:29 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=014262026/11/09 12:11:29 INFO Vacuumed table table=pending_closures14272026/11/09 12:11:29 INFO Vacuumed table table=pending_objects14282026/11/09 12:11:29 INFO Vacuumed table table=multipart_uploads14292026/11/09 12:11:29 INFO Vacuumed table table=closures14302026/11/09 12:11:29 INFO Vacuumed table table=objects1431--- PASS: TestGCSweepDeliversEachKeyOnce (10.98s)1432=== CONT TestCacheConfigHandler1433=== RUN TestCacheConfigHandler/full_config,_no_issuer1434=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1435=== RUN TestCacheConfigHandler/no_cache_url_configured1436=== PAUSE TestCacheConfigHandler/no_cache_url_configured1437=== RUN TestCacheConfigHandler/no_signing_keys1438=== PAUSE TestCacheConfigHandler/no_signing_keys1439=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1440=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1441=== CONT TestService_ReadScope_PublicByDefault14422026/11/09 12:11:29 INFO Received complete push request method=POST path=/api/pushes/1/complete14432026/11/09 12:11:29 INFO Completed push id=1 objects=4 duration=11.072459ms14442026/11/09 12:11:29 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete14452026/11/09 12:11:29 INFO Completed upload id=2 objects=2 duration=4.657416ms1446--- PASS: TestMetricsCommit (9.72s)1447=== CONT TestService_AuthMiddleware_OIDC14482026/11/09 12:11:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50208/oidc14492026/11/09 12:11:29 INFO Aborted multipart uploads count=1 kept=01450--- PASS: TestService_healthCheckHandler (9.73s)1451=== CONT TestService_AuthMiddleware_MTLSProxyHeader14522026/11/09 12:11:29 INFO Received cleanup request method=DELETE path=/api/pending_closures14532026/11/09 12:11:29 INFO Aborted multipart uploads count=1 kept=01454--- PASS: TestPendingCleanupUsesOneCutoff (15.15s)1455=== CONT TestService_RequireScope_OIDC14562026/11/09 12:11:29 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50212/oidc1457--- PASS: TestMetricsInventory (9.55s)1458=== CONT TestService_AuthMiddleware1459=== NAME TestPinProtectsFromGC1460 client_integration_test.go:778: Pinned store path: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestPinProtectsFromGC2171486314/001/store/8891yk2vy2hnvijzi6lxyd23jrm0r69c-pinned-file.txt1461 client_integration_test.go:779: Unpinned store path: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestPinProtectsFromGC2171486314/001/store/84nw0phaw0lg6y8kjk9yphz5jnqpjrxp-unpinned-file.txt1462--- PASS: TestCacheStatsHandler (9.82s)1463=== CONT TestGCAdvisoryLockBlocksConcurrentRun14642026/11/09 12:11:31 INFO Received push request method=POST path=/api/pushes14652026/11/09 12:11:31 INFO Received push request method=POST path=/api/pushes14662026/11/09 12:11:31 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14672026/11/09 12:11:31 INFO Uploading m2drfan2lzqr0md925b1pzq9ww2sh6f0-b (256B)14682026/11/09 12:11:31 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14692026/11/09 12:11:31 INFO Uploading 8891yk2vy2hnvijzi6lxyd23jrm0r69c-pinned-file.txt (128B)14702026/11/09 12:11:31 INFO Uploading flfgkwrqljfvdkin0dp5r8ph8vr6cflg-shared-dep (136B)14712026/11/09 12:11:31 WARN Failed to register uploaded object key=m2drfan2lzqr0md925b1pzq9ww2sh6f0.ls error="server returned 404: 404 page not found\n"14722026/11/09 12:11:31 WARN Failed to register uploaded object key=962zx9j06igv38wb0g0is17q62d8aprh.ls error="server returned 404: 404 page not found\n"14732026/11/09 12:11:31 WARN Failed to register uploaded object key=8891yk2vy2hnvijzi6lxyd23jrm0r69c.ls error="server returned 404: 404 page not found\n"14742026/11/09 12:11:31 WARN Failed to register uploaded object key=flfgkwrqljfvdkin0dp5r8ph8vr6cflg.ls error="server returned 404: 404 page not found\n"14752026/11/09 12:11:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14762026/11/09 12:11:31 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14772026/11/09 12:11:31 WARN Failed to register uploaded object key=nar/0az7dw5zdb00sv47kg9lv3kg6qgb7izj028a5k1xk0z6lykqw8dh.nar.zst error="server returned 404: 404 page not found\n"14782026/11/09 12:11:31 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14792026/11/09 12:11:31 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14802026/11/09 12:11:31 INFO Signed narinfos id=1 count=114812026/11/09 12:11:31 INFO Uploading 1 narinfos14822026/11/09 12:11:31 INFO Signed narinfos id=1 count=314832026/11/09 12:11:31 INFO Uploading 3 narinfos14842026/11/09 12:11:31 WARN Failed to register uploaded object key=m2drfan2lzqr0md925b1pzq9ww2sh6f0.narinfo error="server returned 404: 404 page not found\n"14852026/11/09 12:11:31 WARN Failed to register uploaded object key=flfgkwrqljfvdkin0dp5r8ph8vr6cflg.narinfo error="server returned 404: 404 page not found\n"14862026/11/09 12:11:31 INFO Received complete push request method=POST path=/api/pushes/1/complete14872026/11/09 12:11:31 WARN Failed to register uploaded object key=962zx9j06igv38wb0g0is17q62d8aprh.narinfo error="server returned 404: 404 page not found\n"14882026/11/09 12:11:31 INFO Received complete push request method=POST path=/api/pushes/1/complete14892026/11/09 12:11:31 WARN Failed to register uploaded object key=8891yk2vy2hnvijzi6lxyd23jrm0r69c.narinfo error="server returned 404: 404 page not found\n"14902026/11/09 12:11:31 INFO Completed push id=1 objects=8 duration=17.480834ms14912026/11/09 12:11:31 INFO Upload complete. (528ms)14922026/11/09 12:11:31 INFO Completed push id=1 objects=3 duration=16.505709ms1493=== NAME TestClientPushesUseOnePush1494 client_pushes_test.go:97: Retrieved narinfo from S3:1495 StorePath: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientPushesUseOnePush175879914/001/store/flfgkwrqljfvdkin0dp5r8ph8vr6cflg-shared-dep1496 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1497 Compression: zstd1498 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821499 NarSize: 1361500 References: 1501 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n15022026/11/09 12:11:31 INFO Upload complete. (528ms)1503 client_pushes_test.go:97: Retrieved narinfo from S3:1504 StorePath: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientPushesUseOnePush175879914/001/store/962zx9j06igv38wb0g0is17q62d8aprh-a1505 URL: nar/0az7dw5zdb00sv47kg9lv3kg6qgb7izj028a5k1xk0z6lykqw8dh.nar.zst1506 Compression: zstd1507 NarHash: sha256:0az7dw5zdb00sv47kg9lv3kg6qgb7izj028a5k1xk0z6lykqw8dh1508 NarSize: 2561509 References: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientPushesUseOnePush175879914/001/store/flfgkwrqljfvdkin0dp5r8ph8vr6cflg-shared-dep1510 CA: text:sha256:1jj7qa9dms9a313hw717jlmr3p5qxl5bp4hpzhchhq3vc1j1pdwq1511 client_pushes_test.go:97: Retrieved narinfo from S3:1512 StorePath: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientPushesUseOnePush175879914/001/store/m2drfan2lzqr0md925b1pzq9ww2sh6f0-b1513 URL: nar/0az7dw5zdb00sv47kg9lv3kg6qgb7izj028a5k1xk0z6lykqw8dh.nar.zst1514 Compression: zstd1515 NarHash: sha256:0az7dw5zdb00sv47kg9lv3kg6qgb7izj028a5k1xk0z6lykqw8dh1516 NarSize: 2561517 References: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientPushesUseOnePush175879914/001/store/flfgkwrqljfvdkin0dp5r8ph8vr6cflg-shared-dep1518 CA: text:sha256:1jj7qa9dms9a313hw717jlmr3p5qxl5bp4hpzhchhq3vc1j1pdwq1519--- PASS: TestClientPushesUseOnePush (10.93s)1520=== CONT TestLeadEndsOnShutdown15212026/11/09 12:11:32 INFO Received push request method=POST path=/api/pushes15222026/11/09 12:11:32 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15232026/11/09 12:11:32 INFO Uploading 84nw0phaw0lg6y8kjk9yphz5jnqpjrxp-unpinned-file.txt (128B)15242026/11/09 12:11:32 WARN Failed to register uploaded object key=84nw0phaw0lg6y8kjk9yphz5jnqpjrxp.ls error="server returned 404: 404 page not found\n"15252026/11/09 12:11:32 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15262026/11/09 12:11:32 INFO Signed narinfos id=2 count=115272026/11/09 12:11:32 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"15282026/11/09 12:11:32 INFO Uploading 1 narinfos15292026/11/09 12:11:32 INFO Received complete push request method=POST path=/api/pushes/2/complete15302026/11/09 12:11:32 INFO Completed push id=2 objects=3 duration=5.021416ms15312026/11/09 12:11:32 WARN Failed to register uploaded object key=84nw0phaw0lg6y8kjk9yphz5jnqpjrxp.narinfo error="server returned 404: 404 page not found\n"15322026/11/09 12:11:32 INFO Upload complete. (400ms)15332026/11/09 12:11:32 INFO Received push request method=POST path=/api/pushes15342026/11/09 12:11:32 INFO Starting cleanup of old closures method=DELETE path=/api/closures15352026/11/09 12:11:32 INFO Garbage collection started15362026/11/09 12:11:32 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15372026/11/09 12:11:32 INFO Uploading 1yb5isx7nfq3wb2b41bkj7b1d1dd3bnq-top (264B)15382026/11/09 12:11:32 INFO Uploading x5m5vmmicjc0k92myv8wb5w65l9l0i0g-shared-dep (136B)15392026/11/09 12:11:32 INFO Aborted multipart uploads count=0 kept=015402026/11/09 12:11:32 WARN Force mode enabled - objects will be deleted immediately without grace period15412026/11/09 12:11:32 WARN Failed to register uploaded object key=x5m5vmmicjc0k92myv8wb5w65l9l0i0g.ls error="server returned 404: 404 page not found\n"15422026/11/09 12:11:32 WARN Failed to register uploaded object key=1yb5isx7nfq3wb2b41bkj7b1d1dd3bnq.ls error="server returned 404: 404 page not found\n"15432026/11/09 12:11:32 WARN Failed to register uploaded object key=nar/1z368ryy9wrm6lw5ggawn661hhbdfp3wcsv1m6xn50ra7c8wmm3z.nar.zst error="server returned 404: 404 page not found\n"15442026/11/09 12:11:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15452026/11/09 12:11:32 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15462026/11/09 12:11:32 INFO Signed narinfos id=1 count=215472026/11/09 12:11:32 INFO Uploading 2 narinfos15482026/11/09 12:11:32 WARN Failed to register uploaded object key=1yb5isx7nfq3wb2b41bkj7b1d1dd3bnq.narinfo error="server returned 404: 404 page not found\n"15492026/11/09 12:11:32 INFO Received complete push request method=POST path=/api/pushes/1/complete15502026/11/09 12:11:32 WARN Failed to register uploaded object key=x5m5vmmicjc0k92myv8wb5w65l9l0i0g.narinfo error="server returned 404: 404 page not found\n"15512026/11/09 12:11:32 INFO Completed push id=1 objects=6 duration=35.943708ms15522026/11/09 12:11:33 INFO Upload complete. (601ms)1553=== NAME TestClientSharedPathCommittedMidPush1554 client_integration_test.go:727: Retrieved narinfo from S3:1555 StorePath: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientSharedPathCommittedMidPush132753476/001/store/x5m5vmmicjc0k92myv8wb5w65l9l0i0g-shared-dep1556 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1557 Compression: zstd1558 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821559 NarSize: 1361560 References: 1561 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1562 client_integration_test.go:727: Retrieved narinfo from S3:1563 StorePath: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientSharedPathCommittedMidPush132753476/001/store/1yb5isx7nfq3wb2b41bkj7b1d1dd3bnq-top1564 URL: nar/1z368ryy9wrm6lw5ggawn661hhbdfp3wcsv1m6xn50ra7c8wmm3z.nar.zst1565 Compression: zstd1566 NarHash: sha256:1z368ryy9wrm6lw5ggawn661hhbdfp3wcsv1m6xn50ra7c8wmm3z1567 NarSize: 2641568 References: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientSharedPathCommittedMidPush132753476/001/store/x5m5vmmicjc0k92myv8wb5w65l9l0i0g-shared-dep1569 CA: text:sha256:16b2npd0zkpj8ba4rhnpnqq3yil2s0adha5wzy82l9n0bjp8335a1570=== NAME TestClientMultipleUploads1571 client_integration_test.go:405: Created store path 0: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientMultipleUploads3952586816/001/store/pzxlql68pahfm9252lqqy5z73gzpv7ay-test-file-0.txt1572=== NAME TestClientWithDependencies1573 client_integration_test.go:660: Built derivation: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientWithDependencies1343581471/001/store/mcrz4f3cvnvx5f5h1r2l7810byn74ig7-test-script1574--- PASS: TestClientSharedPathCommittedMidPush (10.86s)1575=== CONT TestResolveDBConnectionString1576=== RUN TestResolveDBConnectionString/flag_wins1577=== PAUSE TestResolveDBConnectionString/flag_wins1578=== RUN TestResolveDBConnectionString/file_when_flag_empty1579=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1580=== RUN TestResolveDBConnectionString/missing_file_is_an_error1581=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1582=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1583=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1584=== RUN TestResolveDBConnectionString/nothing_configured1585=== PAUSE TestResolveDBConnectionString/nothing_configured1586=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1587=== NAME TestClientWithDependencies1588 client_integration_test.go:662: Found 1 dependencies (including self)1589=== NAME TestClientMultipleUploads1590 client_integration_test.go:405: Created store path 1: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientMultipleUploads3952586816/001/store/b81mi2pfwndg4w15ya6y3vl9jaxxr786-test-file-1.txt1591=== NAME TestClientIntegration1592 client_integration_test.go:291: Created store path: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientIntegration2330684283/002/store/wnf53zh7wvinl7bijgr0lhk82kgzz5q1-test-file.txt1593=== NAME TestClientMultipleUploads1594 client_integration_test.go:405: Created store path 2: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientMultipleUploads3952586816/001/store/s3r7pib1nday9y933pi1g9jsfqrkb227-test-file-2.txt15952026/11/09 12:11:33 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=015962026/11/09 12:11:33 INFO Vacuumed table table=pending_closures15972026/11/09 12:11:33 INFO Vacuumed table table=pending_objects15982026/11/09 12:11:33 INFO Vacuumed table table=multipart_uploads15992026/11/09 12:11:33 INFO Vacuumed table table=closures16002026/11/09 12:11:33 INFO Vacuumed table table=objects16012026/11/09 12:11:33 INFO Received uploads request method=POST path=/api/pending_closures16022026/11/09 12:11:33 INFO Received push request method=POST path=/api/pushes1603--- PASS: TestTombstonedObjectOfferedWithoutWaiting (9.60s)1604=== CONT TestConnectWaitsForAPeerMigration16052026/11/09 12:11:33 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16062026/11/09 12:11:33 INFO Uploading mcrz4f3cvnvx5f5h1r2l7810byn74ig7-test-script (136B)16072026/11/09 12:11:33 WARN Failed to register uploaded object key=mcrz4f3cvnvx5f5h1r2l7810byn74ig7.ls error="server returned 404: 404 page not found\n"16082026/11/09 12:11:33 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"16092026/11/09 12:11:33 INFO Received push request method=POST path=/api/pushes16102026/11/09 12:11:33 INFO Received push request method=POST path=/api/pushes16112026/11/09 12:11:33 WARN Failed to register uploaded object key=log/0wwz8m85j8wh9rmn303i33rs3vrbrvp8-test-script.drv error="server returned 404: 404 page not found\n"16122026/11/09 12:11:33 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16132026/11/09 12:11:33 INFO Signed narinfos id=1 count=116142026/11/09 12:11:33 INFO Uploading 1 narinfos16152026/11/09 12:11:33 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16162026/11/09 12:11:33 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16172026/11/09 12:11:33 INFO Uploading b81mi2pfwndg4w15ya6y3vl9jaxxr786-test-file-1.txt (160B)16182026/11/09 12:11:33 INFO Uploading pzxlql68pahfm9252lqqy5z73gzpv7ay-test-file-0.txt (160B)16192026/11/09 12:11:33 INFO Uploading wnf53zh7wvinl7bijgr0lhk82kgzz5q1-test-file.txt (152B)16202026/11/09 12:11:33 INFO Uploading s3r7pib1nday9y933pi1g9jsfqrkb227-test-file-2.txt (160B)16212026/11/09 12:11:34 INFO Received complete push request method=POST path=/api/pushes/1/complete16222026/11/09 12:11:34 WARN Failed to register uploaded object key=mcrz4f3cvnvx5f5h1r2l7810byn74ig7.narinfo error="server returned 404: 404 page not found\n"16232026/11/09 12:11:34 WARN Failed to register uploaded object key=b81mi2pfwndg4w15ya6y3vl9jaxxr786.ls error="server returned 404: 404 page not found\n"16242026/11/09 12:11:34 INFO Completed push id=1 objects=4 duration=84.796583ms16252026/11/09 12:11:34 INFO Upload complete. (725ms)1626=== NAME TestClientWithDependencies1627 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientWithDependencies1343581471/001/store) requires matching store prefix16282026/11/09 12:11:34 WARN Failed to register uploaded object key=wnf53zh7wvinl7bijgr0lhk82kgzz5q1.ls error="server returned 404: 404 page not found\n"16292026/11/09 12:11:34 WARN Failed to register uploaded object key=pzxlql68pahfm9252lqqy5z73gzpv7ay.ls error="server returned 404: 404 page not found\n"16302026/11/09 12:11:34 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16312026/11/09 12:11:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16322026/11/09 12:11:34 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"16332026/11/09 12:11:34 INFO Signed narinfos id=1 count=116342026/11/09 12:11:34 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16352026/11/09 12:11:34 INFO Uploading 1 narinfos16362026/11/09 12:11:34 WARN Failed to register uploaded object key=s3r7pib1nday9y933pi1g9jsfqrkb227.ls error="server returned 404: 404 page not found\n"16372026/11/09 12:11:34 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16382026/11/09 12:11:34 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16392026/11/09 12:11:34 INFO Signed narinfos id=1 count=316402026/11/09 12:11:34 INFO Uploading 3 narinfos16412026/11/09 12:11:34 INFO Received complete push request method=POST path=/api/pushes/1/complete16422026/11/09 12:11:34 WARN Failed to register uploaded object key=wnf53zh7wvinl7bijgr0lhk82kgzz5q1.narinfo error="server returned 404: 404 page not found\n"16432026/11/09 12:11:34 WARN Failed to register uploaded object key=s3r7pib1nday9y933pi1g9jsfqrkb227.narinfo error="server returned 404: 404 page not found\n"16442026/11/09 12:11:34 WARN Failed to register uploaded object key=pzxlql68pahfm9252lqqy5z73gzpv7ay.narinfo error="server returned 404: 404 page not found\n"16452026/11/09 12:11:34 INFO Received complete push request method=POST path=/api/pushes/1/complete16462026/11/09 12:11:34 WARN Failed to register uploaded object key=b81mi2pfwndg4w15ya6y3vl9jaxxr786.narinfo error="server returned 404: 404 page not found\n"16472026/11/09 12:11:34 INFO Completed push id=1 objects=3 duration=56.000334ms16482026/11/09 12:11:34 INFO Upload complete. (662ms)1649--- PASS: TestClientWithDependencies (11.79s)1650=== CONT TestIsValidCachePath/narinfo1651=== CONT TestParseSingleRange/none1652=== CONT TestIsValidCachePath/short_hash1653=== CONT TestIsValidCachePath/wrong_extension1654=== CONT TestIsValidCachePath/leading_slash1655=== CONT TestIsValidCachePath/empty1656=== CONT TestIsValidCachePath/random_path1657=== CONT TestIsValidCachePath/invalid_char_u1658=== CONT TestIsValidCachePath/invalid_char_e1659=== CONT TestIsValidCachePath/traversal_in_middle1660=== CONT TestIsValidCachePath/traversal_parent1661=== CONT TestIsValidCachePath/index.html16622026/11/09 12:11:34 INFO Completed push id=1 objects=9 duration=46.389ms1663=== CONT TestIsValidCachePath/nix-cache-info16642026/11/09 12:11:34 INFO Upload complete. (701ms)1665=== CONT TestIsValidCachePath/realisation1666=== NAME TestClientMultipleUploads1667 client_integration_test.go:416: Uploaded 3 paths in 911.868583ms1668=== CONT TestIsValidCachePath/log1669=== CONT TestIsValidCachePath/ls1670=== CONT TestIsValidCachePath/nar_uncompressed1671=== CONT TestIsValidCachePath/nar_bz21672=== CONT TestIsValidCachePath/nar_xz1673=== CONT TestIsValidCachePath/nar_zst1674=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1675--- PASS: TestIsValidCachePath (0.01s)1676 --- PASS: TestIsValidCachePath/narinfo (0.00s)1677 --- PASS: TestIsValidCachePath/short_hash (0.00s)1678 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1679 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1680 --- PASS: TestIsValidCachePath/empty (0.00s)1681 --- PASS: TestIsValidCachePath/random_path (0.00s)1682 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1683 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1684 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1685 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1686 --- PASS: TestIsValidCachePath/index.html (0.00s)1687 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1688 --- PASS: TestIsValidCachePath/realisation (0.00s)1689 --- PASS: TestIsValidCachePath/log (0.00s)1690 --- PASS: TestIsValidCachePath/ls (0.00s)1691 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1692 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1693 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1694 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1695 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1696=== CONT TestIsValidUploadKey/narinfo1697=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale16982026/11/09 12:11:34 INFO All 1 paths already cached1699=== NAME TestClientIntegration1700 client_integration_test.go:317: Retrieved narinfo from S3:1701 StorePath: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientIntegration2330684283/002/store/wnf53zh7wvinl7bijgr0lhk82kgzz5q1-test-file.txt1702 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1703 Compression: zstd1704 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11705 NarSize: 1521706 References: 1707 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11708 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1709 client_integration_test.go:318: Decompressed .ls content (64 bytes):1710 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1711--- PASS: TestClientMultipleUploads (11.74s)1712=== CONT TestParseSingleRange/start_far_past_EOF1713=== CONT TestParseSingleRange/start_past_EOF1714=== CONT TestParseSingleRange/single_byte1715=== CONT TestParseSingleRange/suffix_exceeds_size1716=== CONT TestParseSingleRange/suffix1717=== CONT TestParseSingleRange/end_clamped_to_size1718=== CONT TestParseSingleRange/open-ended1719=== CONT TestParseSingleRange/closed1720=== CONT TestParseSingleRange/malformed_end_before_start1721=== CONT TestParseSingleRange/malformed_both_empty1722=== CONT TestParseSingleRange/malformed_no_dash1723=== CONT TestParseSingleRange/multi-range_ignored1724=== CONT TestParseSingleRange/unknown_unit1725--- PASS: TestParseSingleRange (0.00s)1726 --- PASS: TestParseSingleRange/none (0.00s)1727 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1728 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1729 --- PASS: TestParseSingleRange/single_byte (0.00s)1730 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1731 --- PASS: TestParseSingleRange/suffix (0.00s)1732 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1733 --- PASS: TestParseSingleRange/open-ended (0.00s)1734 --- PASS: TestParseSingleRange/closed (0.00s)1735 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1736 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1737 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1738 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1739 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1740=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed17412026/11/09 12:11:34 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=017422026/11/09 12:11:34 INFO Received create pin request method=POST path=/api/pins/myapp17432026/11/09 12:11:34 INFO Created/updated pin name=myapp store_path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestPinProtectsFromGC2171486314/001/store/8891yk2vy2hnvijzi6lxyd23jrm0r69c-pinned-file.txt narinfo_key=8891yk2vy2hnvijzi6lxyd23jrm0r69c.narinfo17442026/11/09 12:11:34 INFO Starting cleanup of old closures method=DELETE path=/api/closures17452026/11/09 12:11:34 INFO Garbage collection started17462026/11/09 12:11:34 INFO Aborted multipart uploads count=0 kept=017472026/11/09 12:11:34 WARN Force mode enabled - objects will be deleted immediately without grace period17482026/11/09 12:11:34 INFO Received uploads request method=POST path=/api/pending_closures17492026/11/09 12:11:34 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=017502026/11/09 12:11:34 INFO Vacuumed table table=pending_closures17512026/11/09 12:11:34 INFO Vacuumed table table=pending_objects17522026/11/09 12:11:34 INFO Vacuumed table table=multipart_uploads17532026/11/09 12:11:34 INFO Vacuumed table table=closures17542026/11/09 12:11:34 INFO Vacuumed table table=objects17552026/11/09 12:11:34 INFO Received push request method=POST path=/api/pushes17562026/11/09 12:11:34 INFO Object in database but missing from S3 key=wnf53zh7wvinl7bijgr0lhk82kgzz5q1.ls17572026/11/09 12:11:34 WARN Found objects in DB but missing from S3, will re-upload count=117582026/11/09 12:11:34 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17592026/11/09 12:11:34 INFO Aborted multipart uploads count=0 kept=017602026/11/09 12:11:34 WARN Force mode enabled - objects will be deleted immediately without grace period17612026/11/09 12:11:34 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=017622026/11/09 12:11:35 INFO Received complete push request method=POST path=/api/pushes/2/complete17632026/11/09 12:11:35 WARN Failed to register uploaded object key=wnf53zh7wvinl7bijgr0lhk82kgzz5q1.ls error="server returned 404: 404 page not found\n"17642026/11/09 12:11:35 INFO Completed push id=2 objects=3 duration=8.550542ms17652026/11/09 12:11:35 INFO Upload complete. (250ms)1766=== NAME TestClientIntegration1767 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1768 client_integration_test.go:335: Decompressed .ls content (49 bytes):1769 {"version":1,"root":{"type":"regular","size":39}}17702026/11/09 12:11:35 INFO Vacuumed table table=pending_closures17712026/11/09 12:11:35 INFO Vacuumed table table=pending_objects17722026/11/09 12:11:35 INFO Vacuumed table table=multipart_uploads17732026/11/09 12:11:35 INFO Vacuumed table table=closures1774=== NAME TestOrphanedObjectsGCStressTest1775 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains17762026/11/09 12:11:35 INFO Vacuumed table table=objects1777--- PASS: TestGCSweepSkipsPendingObjects (9.76s)1778=== CONT TestIsValidUploadKey/unknown_type1779=== CONT TestIsValidUploadKey/empty_key1780=== CONT TestIsValidUploadKey/absolute1781=== CONT TestIsValidUploadKey/traversal_nar1782=== CONT TestIsValidUploadKey/traversal1783=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1784=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1785=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1786=== CONT TestIsValidUploadKey/index.html1787=== CONT TestIsValidUploadKey/nix-cache-info1788=== CONT TestIsValidUploadKey/realisation_plus_in_output1789=== CONT TestIsValidUploadKey/realisation1790=== CONT TestIsValidUploadKey/build_log_equals1791=== CONT TestIsValidUploadKey/build_log_question_mark1792=== CONT TestIsValidUploadKey/build_log_plus_in_name1793=== CONT TestIsValidUploadKey/build_log_home-manager_file1794=== CONT TestIsValidUploadKey/build_log1795=== CONT TestIsValidUploadKey/listing1796=== CONT TestIsValidUploadKey/nar_plain1797=== CONT TestIsValidUploadKey/nar_xz1798=== CONT TestIsValidUploadKey/nar_zst1799--- PASS: TestIsValidUploadKey (0.02s)1800 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1801 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1802 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1803 --- PASS: TestIsValidUploadKey/absolute (0.00s)1804 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1805 --- PASS: TestIsValidUploadKey/traversal (0.00s)1806 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1807 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1808 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1809 --- PASS: TestIsValidUploadKey/index.html (0.00s)1810 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1811 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1812 --- PASS: TestIsValidUploadKey/realisation (0.00s)1813 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1814 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1815 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1816 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1817 --- PASS: TestIsValidUploadKey/build_log (0.00s)1818 --- PASS: TestIsValidUploadKey/listing (0.00s)1819 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1820 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1821 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1822=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18232026/11/09 12:11:35 INFO Received uploads request method=POST path=/api/pending_closures1824=== NAME TestOrphanedObjectsGCStressTest1825 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1826=== NAME TestClientCADerivations1827 client_ca_test.go:136: Built CA derivation: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientCADerivations1936837694/001/store/km0mk5mkbpfwm9hiz60qf4w8bajfcmbs-ca-test1828--- PASS: TestDeduplicatedObjectsRecordedAsPending (9.24s)1829=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info18302026/11/09 12:11:35 INFO Received uploads request method=POST path=/1831=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1832=== NAME TestClientCADerivations1833 client_ca_test.go:139: Found 1 dependencies (including self)18342026/11/09 12:11:35 INFO Received push request method=POST path=/api/pushes18352026/11/09 12:11:35 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)18362026/11/09 12:11:35 INFO Received complete push request method=POST path=/api/pushes/3/complete18372026/11/09 12:11:35 WARN Failed to register uploaded object key=wnf53zh7wvinl7bijgr0lhk82kgzz5q1.ls error="server returned 404: 404 page not found\n"18382026/11/09 12:11:35 INFO Completed push id=3 objects=3 duration=4.368208ms18392026/11/09 12:11:35 INFO Upload complete. (392ms)1840=== NAME TestClientIntegration1841 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1842 client_integration_test.go:352: Decompressed .ls content (49 bytes):1843 {"version":1,"root":{"type":"regular","size":39}}1844 client_integration_test.go:363: Testing garbage collection...18452026/11/09 12:11:36 INFO Received uploads request method=POST path=/api/pending_closures18462026/11/09 12:11:36 INFO Received push request method=POST path=/api/pushes18472026/11/09 12:11:36 INFO Starting cleanup of old closures method=DELETE path=/api/closures18482026/11/09 12:11:36 INFO Garbage collection started18492026/11/09 12:11:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18502026/11/09 12:11:36 INFO Uploading km0mk5mkbpfwm9hiz60qf4w8bajfcmbs-ca-test (144B)18512026/11/09 12:11:36 INFO Aborted multipart uploads count=0 kept=018522026/11/09 12:11:36 INFO lead: acquired remote=192.0.2.1:123418532026/11/09 12:11:36 INFO lead: released remote=192.0.2.1:12341854--- PASS: TestLeadIncumbentAnnouncesAtOnce (8.81s)18552026/11/09 12:11:36 WARN Force mode enabled - objects will be deleted immediately without grace period1856=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed18572026/11/09 12:11:36 WARN Failed to register uploaded object key=km0mk5mkbpfwm9hiz60qf4w8bajfcmbs.ls error="server returned 404: 404 page not found\n"18582026/11/09 12:11:36 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"18592026/11/09 12:11:36 WARN Failed to register uploaded object key=log/nzcf0y7f12w3hmlbdz509lnsgy7bpzns-ca-test.drv error="server returned 404: 404 page not found\n"18602026/11/09 12:11:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18612026/11/09 12:11:36 INFO Signed narinfos id=1 count=118622026/11/09 12:11:36 INFO Aborted multipart uploads count=0 kept=018632026/11/09 12:11:36 INFO Uploading 1 narinfos18642026/11/09 12:11:36 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=018652026/11/09 12:11:36 INFO Received complete push request method=POST path=/api/pushes/1/complete18662026/11/09 12:11:36 WARN Failed to register uploaded object key=km0mk5mkbpfwm9hiz60qf4w8bajfcmbs.narinfo error="server returned 404: 404 page not found\n"18672026/11/09 12:11:36 INFO Vacuumed table table=pending_closures18682026/11/09 12:11:36 INFO Completed push id=1 objects=4 duration=48.337709ms18692026/11/09 12:11:36 INFO Upload complete. (766ms)1870=== NAME TestClientCADerivations1871 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientCADerivations1936837694/001/store/km0mk5mkbpfwm9hiz60qf4w8bajfcmbs-ca-test1872 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst18732026/11/09 12:11:36 INFO Vacuumed table table=pending_objects1874 Compression: zstd1875 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1876 NarSize: 1441877 References: 1878 Deriver: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientCADerivations1936837694/001/store/nzcf0y7f12w3hmlbdz509lnsgy7bpzns-ca-test.drv1879 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1880 client_ca_test.go:185: Checking for realisation files in S3...18812026/11/09 12:11:36 INFO Vacuumed table table=multipart_uploads1882 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1883 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache18842026/11/09 12:11:36 INFO Vacuumed table table=closures18852026/11/09 12:11:36 INFO Vacuumed table table=objects18862026/11/09 12:11:36 INFO Aborted multipart uploads count=0 kept=018872026/11/09 12:11:36 WARN Force mode enabled - objects will be deleted immediately without grace period18882026/11/09 12:11:36 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=01889=== NAME TestPinProtectsFromGC1890 client_integration_test.go:887: Pin successfully protected closure from garbage collection18912026/11/09 12:11:36 INFO lead: acquired remote=192.0.2.1:123418922026/11/09 12:11:36 INFO Vacuumed table table=pending_closures18932026/11/09 12:11:36 INFO Vacuumed table table=pending_objects18942026/11/09 12:11:36 INFO Vacuumed table table=multipart_uploads18952026/11/09 12:11:36 INFO Vacuumed table table=closures18962026/11/09 12:11:36 INFO Vacuumed table table=objects1897--- PASS: TestPushDedupSurvivesConcurrentGC (10.55s)1898=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1899=== NAME TestClientCADerivations1900 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket74?endpoint=http://localhost:49925®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestClientCADerivations1936837694/001/store'1901 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 119022026/11/09 12:11:36 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=01903--- PASS: TestPinProtectsFromGC (15.36s)1904=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed19052026/11/09 12:11:37 INFO Vacuumed table table=pending_closures1906--- PASS: TestClientCADerivations (12.02s)1907=== CONT TestPendingClosureWriteTimeout/empty1908=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19092026/11/09 12:11:37 INFO Vacuumed table table=pending_objects19102026/11/09 12:11:37 INFO Received request for more parts method=POST path=/1911=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19122026/11/09 12:11:37 INFO Received complete multipart upload request method=POST path=/1913=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19142026/11/09 12:11:37 INFO Received uploads request method=POST path=/1915--- PASS: TestUploadHandlersRejectInvalidKeys (0.08s)1916 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1917 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1918 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1919 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1920=== CONT TestGCEndsOnShutdown/before_the_run19212026/11/09 12:11:37 INFO Vacuumed table table=multipart_uploads19222026/11/09 12:11:37 INFO Vacuumed table table=closures19232026/11/09 12:11:37 INFO Vacuumed table table=objects19242026/11/09 12:11:37 INFO Aborted multipart uploads count=0 kept=019252026/11/09 12:11:37 WARN Force mode enabled - objects will be deleted immediately without grace period19262026/11/09 12:11:37 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=019272026/11/09 12:11:37 INFO Vacuumed table table=pending_closures19282026/11/09 12:11:37 INFO Vacuumed table table=pending_objects19292026/11/09 12:11:37 INFO Vacuumed table table=multipart_uploads19302026/11/09 12:11:37 INFO Vacuumed table table=closures19312026/11/09 12:11:37 INFO Vacuumed table table=objects1932--- PASS: TestGCMetrics (9.49s)1933=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1934--- PASS: TestService_ReadAuthMiddleware (9.11s)1935=== CONT TestPendingClosureWriteTimeout/670k_objects1936=== CONT TestPendingClosureWriteTimeout/400_objects1937=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark19382026/11/09 12:11:38 INFO lead: released remote=192.0.2.1:123419392026/11/09 12:11:38 INFO lead: acquired remote=192.0.2.1:123419402026/11/09 12:11:38 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19412026/11/09 12:11:38 WARN mTLS auth: bound subjects configured but subject DN unavailable19422026/11/09 12:11:38 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1943--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (9.29s)1944=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19452026/11/09 12:11:38 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01946=== NAME TestClientIntegration1947 client_integration_test.go:370: Objects in database after GC:1948 client_integration_test.go:370: Successfully deleted all objects with GC --force1949--- PASS: TestClientIntegration (15.21s)1950=== CONT TestProxyWriteTimeout/narinfo1951=== CONT TestProxyWriteTimeout/10_GiB_nar1952=== CONT TestProxyWriteTimeout/unknown_size1953=== CONT TestProxyWriteTimeout/1_GiB_nar1954--- PASS: TestProxyWriteTimeout (0.03s)1955 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1956 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1957 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1958 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1959=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19602026/11/09 12:11:38 INFO Received uploads request method=POST path=/19612026/11/09 12:11:39 INFO lead: released remote=192.0.2.1:12341962--- PASS: TestGCBugBareHashReferences (9.75s)1963=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19642026/11/09 12:11:39 INFO Received request for more parts method=POST path=/1965--- PASS: TestLeadElectsOneAndHandsOver (11.37s)1966=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart19672026/11/09 12:11:39 INFO Received complete multipart upload request method=POST path=/1968=== CONT TestPush_RejectsBadRequests/no_roots1969=== CONT TestPush_RejectsBadRequests/bad_root19702026/11/09 12:11:39 INFO Received push request method=POST path=/api/pushes1971--- PASS: TestUploadHandlersRejectOversizedBody (0.24s)1972 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.76s)1973 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.10s)1974 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.08s)1975=== CONT TestPush_RejectsBadRequests/root_not_in_objects19762026/11/09 12:11:39 INFO Received push request method=POST path=/api/pushes19772026/11/09 12:11:39 INFO Received push request method=POST path=/api/pushes1978=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1979=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1980=== CONT TestPush_RejectsBadRequests/no_objects19812026/11/09 12:11:39 INFO Received push request method=POST path=/api/pushes1982=== CONT TestServerTLSConfig/no_client_CA1983=== CONT TestServerTLSConfig/not_a_PEM_file1984--- PASS: TestPush_RejectsBadRequests (4.31s)1985 --- PASS: TestPush_RejectsBadRequests/no_roots (0.01s)1986 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1987 --- PASS: TestPush_RejectsBadRequests/bad_root (0.01s)1988 --- PASS: TestPush_RejectsBadRequests/no_objects (0.02s)1989=== CONT TestServerTLSConfig/missing_CA_file1990=== CONT TestClientErrorHandling/ServerNotAvailable1991--- PASS: TestService_ReadScope_PublicByDefault (9.87s)1992--- PASS: TestServerTLSConfig (0.00s)1993 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1994 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)1995 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1996=== CONT TestClientErrorHandling/InvalidStorePath1997=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1998=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1999=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2000=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2001=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2002=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2003=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2004=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2005=== CONT TestClientErrorHandling/InvalidAuthToken20062026/11/09 12:11:39 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/present20072026/11/09 12:11:39 WARN Request failed, retrying attempt=2 backoff=188.123108ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20082026/11/09 12:11:40 WARN Request failed, retrying attempt=3 backoff=406.95098ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2009--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (10.62s)2010=== CONT TestCacheConfigHandler/full_config,_no_issuer2011=== CONT TestCacheConfigHandler/no_signing_keys2012=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2013=== CONT TestCacheConfigHandler/no_cache_url_configured2014--- PASS: TestCacheConfigHandler (0.00s)2015 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2016 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2017 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2018 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2019=== CONT TestResolveDBConnectionString/flag_wins2020=== CONT TestResolveDBConnectionString/nothing_configured2021=== CONT TestResolveDBConnectionString/PGHOST_allows_empty2022=== CONT TestResolveDBConnectionString/missing_file_is_an_error2023=== CONT TestResolveDBConnectionString/file_when_flag_empty2024=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2025=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2026=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2027--- PASS: TestResolveDBConnectionString (0.02s)2028 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)2029 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)2030 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)2031 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)2032 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)20332026/11/09 12:11:40 WARN Authentication failed token_preview=eyJhbGciOi...KWdaLAMqRw token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2034=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20352026/11/09 12:11:40 WARN Authentication failed token_preview=not-a-valid-jwt token_length=15 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]2036--- PASS: TestService_AuthMiddleware_OIDC (10.28s)2037 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2038 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2039 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2040 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)20412026/11/09 12:11:40 WARN Request failed, retrying attempt=4 backoff=829.620768ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2042=== RUN TestService_RequireScope_OIDC/builder_may_write2043=== PAUSE TestService_RequireScope_OIDC/builder_may_write2044=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2045=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2046=== RUN TestService_RequireScope_OIDC/ops_may_admin2047=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2048=== RUN TestService_RequireScope_OIDC/ops_may_not_write2049=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2050=== RUN TestService_RequireScope_OIDC/reader_may_not_write2051=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2052=== RUN TestService_RequireScope_OIDC/static_token_may_admin2053=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2054=== RUN TestService_RequireScope_OIDC/static_token_may_write2055=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2056=== RUN TestService_RequireScope_OIDC/reader_may_read2057=== PAUSE TestService_RequireScope_OIDC/reader_may_read2058=== RUN TestService_RequireScope_OIDC/writer_implies_read2059=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2060=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2061=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2062=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc2063=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc2064=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2065=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2066=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2067=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2068=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2069=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2070=== CONT TestService_RequireScope_OIDC/builder_may_write2071=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2072=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20732026/11/09 12:11:40 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]2074=== CONT TestService_RequireScope_OIDC/static_token_may_write2075=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2076=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2077=== CONT TestService_RequireScope_OIDC/writer_implies_read2078=== CONT TestService_RequireScope_OIDC/reader_may_read2079=== CONT TestService_RequireScope_OIDC/ops_may_not_write2080=== CONT TestService_RequireScope_OIDC/static_token_may_admin2081=== CONT TestService_RequireScope_OIDC/reader_may_not_write2082=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2083=== CONT TestService_RequireScope_OIDC/ops_may_admin2084=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2085--- PASS: TestService_RequireScope_OIDC (11.09s)2086 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2087 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2088 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2089 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2090 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2091 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2092 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2093 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2094 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2095 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2096 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2097 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2098 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2099 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2100--- PASS: TestConnectWaitsForAPeerMigration (7.51s)21012026/11/09 12:11:41 WARN Request failed, retrying attempt=5 backoff=1.577070855s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21022026/11/09 12:11:41 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"2103--- PASS: TestService_AuthMiddleware (11.21s)21042026/11/09 12:11:41 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld5 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"2105--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (10.64s)21062026/11/09 12:11:42 INFO lead: acquired remote=192.0.2.1:123421072026/11/09 12:11:43 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-config21082026/11/09 12:11:43 WARN Request failed, retrying attempt=2 backoff=214.442046ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21092026/11/09 12:11:43 INFO Received uploads request method=POST path=/api/pending_closures21102026/11/09 12:11:43 INFO lead: released remote=192.0.2.1:12342111--- PASS: TestLeadEndsOnShutdown (11.38s)21122026/11/09 12:11:43 WARN Request failed, retrying attempt=3 backoff=384.508624ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21132026/11/09 12:11:43 INFO Received uploads request method=POST path=/api/pending_closures21142026/11/09 12:11:43 WARN Request failed, retrying attempt=4 backoff=863.048756ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2115--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (10.89s)21162026/11/09 12:11:44 INFO Received uploads request method=POST path=/api/pending_closures2117--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2118 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (9.12s)2119 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (9.35s)21202026/11/09 12:11:44 WARN Request failed, retrying attempt=5 backoff=1.689186767s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21212026/11/09 12:11:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21222026/11/09 12:11:45 INFO Received uploads request method=POST path=/api/pending_closures21232026/11/09 12:11:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLjM0MTE1OTJmLTgwODUtNDQ5YS05MWViLWU2MWVmOWZjMzdmM3gxNzk0MjI2MzAzMzI2NDU4MDAw parts=1021242026/11/09 12:11:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21252026/11/09 12:11:45 INFO Completed upload id=1 objects=3 duration=17.261917ms21262026/11/09 12:11:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21272026/11/09 12:11:45 INFO Received uploads request method=POST path=/api/pending_closures21282026/11/09 12:11:45 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLjBlYTBkMzI2LWE1NDEtNDFhMi1iOTlhLWU1MTg0YzM0NjE3YngxNzk0MjI2MzAzNjc5ODgyMDAw parts=1021292026/11/09 12:11:45 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21302026/11/09 12:11:45 INFO Completed upload id=1 objects=3 duration=12.73875ms21312026/11/09 12:11:45 INFO Received uploads request method=POST path=/api/pending_closures21322026/11/09 12:11:45 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21332026/11/09 12:11:45 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21342026/11/09 12:11:45 INFO Received uploads request method=POST path=/api/pending_closures21352026/11/09 12:11:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21362026/11/09 12:11:46 INFO Received uploads request method=POST path=/api/pending_closures21372026/11/09 12:11:46 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21382026/11/09 12:11:46 WARN Found objects in DB but missing from S3, will re-upload count=121392026/11/09 12:11:46 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLjUzYjQxMjNhLThjNzUtNGVmYy04ZWUzLWI0NzY4NTE0N2U0MXgxNzk0MjI2MzA0Mzc5Nzk0MDAw parts=1021402026/11/09 12:11:46 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"21412026/11/09 12:11:46 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-config21422026/11/09 12:11:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21432026/11/09 12:11:46 INFO Completed upload id=1 objects=3 duration=15.883333ms21442026/11/09 12:11:46 INFO Received uploads request method=POST path=/api/pending_closures21452026/11/09 12:11:46 WARN Request failed, retrying attempt=2 backoff=187.635636ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21462026/11/09 12:11:46 INFO Aborted multipart uploads count=0 kept=021472026/11/09 12:11:46 WARN Force mode enabled - objects will be deleted immediately without grace period21482026-11-09 12:11:46.556 UTC [50209] ERROR: canceling statement due to user request21492026-11-09 12:11:46.556 UTC [50209] STATEMENT: -- name: MarkStaleObjects :execrows2150 WITH RECURSIVE ct AS (2151 SELECT timezone('UTC', now()) AS now2152 ),2153 closure_reach AS (2154 -- Start with all closure keys2155 SELECT o.key, o.refs2156 FROM objects o2157 INNER JOIN closures c ON o.key = c.key2158 UNION2159 -- Recursively add all referenced objects2160 SELECT o.key, o.refs2161 FROM objects o2162 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2163 ),2164 reachable_objects AS (2165 SELECT DISTINCT key FROM closure_reach2166 ),2167 stale_objects AS (2168 SELECT o.key2169 FROM objects AS o, ct2170 WHERE2171 NOT EXISTS (2172 SELECT 12173 FROM reachable_objects ro2174 WHERE ro.key = o.key2175 )2176 AND NOT EXISTS (2177 SELECT 12178 FROM pending_objects AS po2179 WHERE po.key = o.key2180 )2181 AND o.deleted_at IS NULL -- Only mark fresh objects2182 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2183 FOR UPDATE2184 )2185 UPDATE objects2186 SET2187 deleted_at = ct.now,2188 first_deleted_at = COALESCE(first_deleted_at, ct.now)2189 FROM stale_objects, ct2190 WHERE objects.key = stale_objects.key2191 21922026/11/09 12:11:46 WARN Request failed, retrying attempt=3 backoff=390.247145ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2193--- PASS: TestPendingClosureWriteTimeout (0.08s)2194 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2195 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2196 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2197 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (9.52s)21982026/11/09 12:11:46 INFO Aborted multipart uploads count=0 kept=021992026/11/09 12:11:46 WARN Force mode enabled - objects will be deleted immediately without grace period22002026/11/09 12:11:46 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:49925/bucket102/?delete=\": context canceled"2201--- PASS: TestGCEndsOnShutdown (0.00s)2202 --- PASS: TestGCEndsOnShutdown/before_the_run (7.79s)2203 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (9.01s)2204 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (8.86s)22052026/11/09 12:11:47 WARN Request failed, retrying attempt=4 backoff=795.013583ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22062026/11/09 12:11:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22072026/11/09 12:11:47 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLmFlY2FhZmE5LTMwYmItNDA0Ny05MWRmLTc3YTk3ODE1OGJmYXgxNzk0MjI2MzA1MTk0NzMzMDAw parts=1022082026/11/09 12:11:47 INFO Received uploads request method=POST path=/api/pending_closures22092026/11/09 12:11:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22102026/11/09 12:11:47 INFO Completed upload id=1 objects=3 duration=19.011125ms22112026/11/09 12:11:47 INFO Received uploads request method=POST path=/api/pending_closures22122026/11/09 12:11:47 INFO Aborted multipart uploads count=0 kept=022132026/11/09 12:11:47 WARN Force mode enabled - objects will be deleted immediately without grace period22142026/11/09 12:11:47 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=022152026/11/09 12:11:47 INFO Vacuumed table table=pending_closures22162026/11/09 12:11:47 INFO Vacuumed table table=pending_objects22172026/11/09 12:11:47 INFO Vacuumed table table=multipart_uploads22182026/11/09 12:11:47 INFO Vacuumed table table=closures22192026/11/09 12:11:47 INFO Vacuumed table table=objects22202026/11/09 12:11:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22212026/11/09 12:11:47 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLjE0OTJlYzI4LTM4ZGEtNDdlYi1hYzgxLTAwNTM0MjA2MmY3NXgxNzk0MjI2MzA1NTk4MzA4MDAw parts=1022222026/11/09 12:11:47 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22232026/11/09 12:11:47 INFO Completed upload id=1 objects=3 duration=14.980208ms22242026/11/09 12:11:47 INFO Received uploads request method=POST path=/api/pending_closures22252026/11/09 12:11:47 INFO Received uploads request method=POST path=/api/pending_closures22262026/11/09 12:11:47 INFO Aborted multipart uploads count=0 kept=022272026/11/09 12:11:47 WARN Force mode enabled - objects will be deleted immediately without grace period22282026/11/09 12:11:47 WARN Request failed, retrying attempt=5 backoff=1.471886399s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22292026/11/09 12:11:48 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=022302026/11/09 12:11:48 INFO Vacuumed table table=pending_closures22312026/11/09 12:11:48 INFO Vacuumed table table=pending_objects22322026/11/09 12:11:48 INFO Vacuumed table table=multipart_uploads22332026/11/09 12:11:48 INFO Vacuumed table table=closures22342026/11/09 12:11:48 INFO Vacuumed table table=objects2235--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2236 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (8.30s)2237 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (9.13s)22382026/11/09 12:11:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22392026/11/09 12:11:48 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLmQ1OTlkZWQ3LTBlNzEtNGZkNi05Yjk5LTI0YjQwNzA3ZWQ1OXgxNzk0MjI2MzA2NDg4NDE0MDAw parts=1022402026/11/09 12:11:48 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22412026/11/09 12:11:48 INFO Completed upload id=2 objects=3 duration=1.475583ms22422026/11/09 12:11:48 INFO Received uploads request method=POST path=/api/pending_closures22432026/11/09 12:11:48 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22442026/11/09 12:11:48 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22452026/11/09 12:11:48 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22462026/11/09 12:11:49 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22472026/11/09 12:11:49 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22482026/11/09 12:11:49 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=ZGI5YzgyMzQtNmQ5Ny00YWYxLTg3MmYtNmViYzE4YmYyNmVmLjIyZTE2MTVmLWJkNTItNGY0Yi1hOWEzLTYyNzIwOTI0YWUxN3gxNzk0MjI2MzA3NzE3OTMwMDAw parts=1022492026/11/09 12:11:49 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22502026/11/09 12:11:49 INFO Completed upload id=2 objects=3 duration=966.125µs22512026/11/09 12:11:49 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_closures22522026/11/09 12:11:49 WARN Request failed, retrying attempt=2 backoff=207.401779ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22532026/11/09 12:11:49 INFO Received uploads request method=POST path=/api/pending_closures22542026/11/09 12:11:49 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22552026/11/09 12:11:49 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2256--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.08s)2257 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (11.23s)2258 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (11.05s)2259 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (10.41s)2260 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (12.65s)2261 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (12.73s)22622026/11/09 12:11:49 WARN Request failed, retrying attempt=3 backoff=360.580009ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22632026/11/09 12:11:50 WARN Request failed, retrying attempt=4 backoff=847.911537ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22642026/11/09 12:11:50 WARN Request failed, retrying attempt=5 backoff=1.675633648s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2265--- PASS: TestClientErrorHandling (0.00s)2266 --- PASS: TestClientErrorHandling/InvalidStorePath (8.75s)2267 --- PASS: TestClientErrorHandling/InvalidAuthToken (9.24s)2268 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.38s)2269=== NAME TestOrphanedObjectsGCStressTest2270 orphaned_objects_gc_test.go:503: Stress test completed successfully:2271 orphaned_objects_gc_test.go:504: - Active objects preserved: 202272 orphaned_objects_gc_test.go:505: - Objects deleted: 2102273 orphaned_objects_gc_test.go:506: - Total GC'd: 2102274--- PASS: TestOrphanedObjectsGCStressTest (47.13s)2275PASS2276{"timestamp":"2026-11-09T12:11:55.506232Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:50314","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(3)"}2277{"timestamp":"2026-11-09T12:11:55.508282Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:50315","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(6)"}2278{"timestamp":"2026-11-09T12:11:55.508209Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:50459","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(7)"}22792026-11-09 12:11:55.651 UTC [48653] LOG: received smart shutdown request22802026-11-09 12:11:55.654 UTC [48653] LOG: background worker "logical replication launcher" (PID 48687) exited with exit code 122812026-11-09 12:11:55.659 UTC [48676] LOG: shutting down22822026-11-09 12:11:55.659 UTC [48676] LOG: checkpoint starting: shutdown immediate22832026-11-09 12:11:58.238 UTC [48676] LOG: checkpoint complete: wrote 12021 buffers (73.4%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=1.153 s, sync=1.375 s, total=2.580 s; sync files=36061, longest=0.010 s, average=0.001 s; distance=529861 kB, estimate=529861 kB; lsn=0/21CFE510, redo lsn=0/21CFE51022842026-11-09 12:11:58.257 UTC [48653] LOG: database system is shut down2285Running OIDC tests...2286=== RUN TestAudienceForIssuer2287=== PAUSE TestAudienceForIssuer2288=== RUN TestGlobMatch2289=== PAUSE TestGlobMatch2290=== RUN TestValidateToken_ValidToken2291=== PAUSE TestValidateToken_ValidToken2292=== RUN TestValidateToken_WrongAudience2293=== PAUSE TestValidateToken_WrongAudience2294=== RUN TestValidateToken_Expired2295=== PAUSE TestValidateToken_Expired2296=== RUN TestValidateToken_BoundClaimsMismatch2297=== PAUSE TestValidateToken_BoundClaimsMismatch2298=== RUN TestValidateToken_BoundSubjectMismatch2299=== PAUSE TestValidateToken_BoundSubjectMismatch2300=== RUN TestValidateToken_MultipleProviders2301=== PAUSE TestValidateToken_MultipleProviders2302=== RUN TestValidateToken_NoMatchingProvider2303=== PAUSE TestValidateToken_NoMatchingProvider2304=== RUN TestValidateToken_KubernetesServiceAccount2305=== PAUSE TestValidateToken_KubernetesServiceAccount2306=== RUN TestNewValidator_KubernetesRequiresCA2307=== PAUSE TestNewValidator_KubernetesRequiresCA2308=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2309=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2310=== RUN TestPins_ReservedForMatchingRule2311=== PAUSE TestPins_ReservedForMatchingRule2312=== RUN TestPins_TopLevelShorthand2313=== PAUSE TestPins_TopLevelShorthand2314=== RUN TestPins_ConfigValidation2315=== PAUSE TestPins_ConfigValidation2316=== RUN TestScopes_LegacyProviderDefaultsToWrite2317=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2318=== RUN TestScopes_Rules2319=== PAUSE TestScopes_Rules2320=== RUN TestScopes_ConfigValidation2321=== PAUSE TestScopes_ConfigValidation2322=== CONT TestAudienceForIssuer2323--- PASS: TestAudienceForIssuer (0.00s)2324=== CONT TestScopes_ConfigValidation2325=== CONT TestPins_TopLevelShorthand2326=== CONT TestValidateToken_ValidToken2327=== CONT TestValidateToken_BoundClaimsMismatch2328=== CONT TestGlobMatch2329=== RUN TestGlobMatch/foo_foo2330=== PAUSE TestGlobMatch/foo_foo2331=== RUN TestGlobMatch/foo_bar2332=== PAUSE TestGlobMatch/foo_bar2333=== RUN TestGlobMatch/*_2334=== PAUSE TestGlobMatch/*_2335=== RUN TestGlobMatch/*_anything2336=== PAUSE TestGlobMatch/*_anything2337=== RUN TestGlobMatch/foo*_foo2338=== PAUSE TestGlobMatch/foo*_foo2339=== RUN TestGlobMatch/foo*_foobar2340=== PAUSE TestGlobMatch/foo*_foobar2341=== RUN TestGlobMatch/foo*_bar2342=== PAUSE TestGlobMatch/foo*_bar2343=== RUN TestGlobMatch/*bar_bar2344=== PAUSE TestGlobMatch/*bar_bar2345=== RUN TestGlobMatch/*bar_foobar2346=== PAUSE TestGlobMatch/*bar_foobar2347=== RUN TestGlobMatch/*bar_foo2348=== PAUSE TestGlobMatch/*bar_foo2349=== RUN TestGlobMatch/foo*bar_foobar2350=== PAUSE TestGlobMatch/foo*bar_foobar2351=== RUN TestGlobMatch/foo*bar_foo123bar2352=== PAUSE TestGlobMatch/foo*bar_foo123bar2353=== RUN TestGlobMatch/foo*bar_foobarbaz2354=== PAUSE TestGlobMatch/foo*bar_foobarbaz2355=== CONT TestValidateToken_KubernetesServiceAccount2356=== CONT TestPins_ReservedForMatchingRule2357--- PASS: TestScopes_ConfigValidation (0.00s)2358=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2359=== CONT TestNewValidator_KubernetesRequiresCA2360=== CONT TestScopes_LegacyProviderDefaultsToWrite2361=== CONT TestScopes_Rules2362=== CONT TestValidateToken_MultipleProviders2363=== CONT TestValidateToken_NoMatchingProvider2364=== CONT TestValidateToken_BoundSubjectMismatch2365=== CONT TestPins_ConfigValidation2366=== CONT TestValidateToken_WrongAudience2367--- PASS: TestPins_ConfigValidation (0.00s)2368=== CONT TestValidateToken_Expired2369=== RUN TestGlobMatch/*/*_foo/bar2370=== PAUSE TestGlobMatch/*/*_foo/bar2371=== RUN TestGlobMatch/*/*_foo2372=== PAUSE TestGlobMatch/*/*_foo2373=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2374=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2375=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02376=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02377=== RUN TestGlobMatch/refs/*/main_refs/heads/main2378=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2379=== RUN TestGlobMatch/fo?_foo2380=== PAUSE TestGlobMatch/fo?_foo2381=== RUN TestGlobMatch/fo?_fo2382=== PAUSE TestGlobMatch/fo?_fo2383=== RUN TestGlobMatch/fo?_fooo2384=== PAUSE TestGlobMatch/fo?_fooo2385=== RUN TestGlobMatch/?oo_foo2386=== PAUSE TestGlobMatch/?oo_foo2387=== RUN TestGlobMatch/?oo_boo2388=== PAUSE TestGlobMatch/?oo_boo2389=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2390=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2391=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2392=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2393=== CONT TestGlobMatch/foo_foo2394=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2395=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2396=== CONT TestGlobMatch/?oo_boo2397=== CONT TestGlobMatch/?oo_foo2398=== CONT TestGlobMatch/fo?_fooo2399=== CONT TestGlobMatch/fo?_fo2400=== CONT TestGlobMatch/fo?_foo2401=== CONT TestGlobMatch/refs/*/main_refs/heads/main2402=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02403=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2404=== CONT TestGlobMatch/*/*_foo2405=== CONT TestGlobMatch/*/*_foo/bar2406=== CONT TestGlobMatch/foo*bar_foobarbaz2407=== CONT TestGlobMatch/foo*bar_foo123bar2408=== CONT TestGlobMatch/foo*bar_foobar2409=== CONT TestGlobMatch/*bar_foo2410=== CONT TestGlobMatch/*bar_foobar2411=== CONT TestGlobMatch/*bar_bar2412=== CONT TestGlobMatch/foo*_bar2413=== CONT TestGlobMatch/foo*_foobar2414=== CONT TestGlobMatch/foo*_foo2415=== CONT TestGlobMatch/*_anything2416=== CONT TestGlobMatch/*_2417=== CONT TestGlobMatch/foo_bar2418--- PASS: TestGlobMatch (0.05s)2419 --- PASS: TestGlobMatch/foo_foo (0.00s)2420 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2421 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2422 --- PASS: TestGlobMatch/?oo_boo (0.00s)2423 --- PASS: TestGlobMatch/?oo_foo (0.00s)2424 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2425 --- PASS: TestGlobMatch/fo?_fo (0.00s)2426 --- PASS: TestGlobMatch/fo?_foo (0.00s)2427 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2428 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2429 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2430 --- PASS: TestGlobMatch/*/*_foo (0.00s)2431 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2432 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2433 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2434 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2435 --- PASS: TestGlobMatch/*bar_foo (0.00s)2436 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2437 --- PASS: TestGlobMatch/*bar_bar (0.00s)2438 --- PASS: TestGlobMatch/foo*_bar (0.00s)2439 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2440 --- PASS: TestGlobMatch/foo*_foo (0.00s)2441 --- PASS: TestGlobMatch/*_anything (0.00s)2442 --- PASS: TestGlobMatch/*_ (0.00s)2443 --- PASS: TestGlobMatch/foo_bar (0.00s)24442026/11/09 12:12:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50480/oidc24452026/11/09 12:12:00 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324462026/11/09 12:12:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50482/oidc24472026/11/09 12:12:00 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:504792448--- PASS: TestValidateToken_BoundClaimsMismatch (0.14s)2449--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.14s)24502026/11/09 12:12:00 http: TLS handshake error from 127.0.0.1:50489: read tcp 127.0.0.1:50485->127.0.0.1:50489: use of closed network connection2451--- PASS: TestNewValidator_KubernetesRequiresCA (0.21s)24522026/11/09 12:12:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50490/oidc24532026/11/09 12:12:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50492/oidc24542026/11/09 12:12:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50495/oidc2455--- PASS: TestPins_TopLevelShorthand (0.22s)2456--- PASS: TestValidateToken_ValidToken (0.22s)2457--- PASS: TestValidateToken_WrongAudience (0.21s)2458--- PASS: TestValidateToken_KubernetesServiceAccount (0.24s)2459--- PASS: TestPins_ReservedForMatchingRule (0.25s)24602026/11/09 12:12:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50498/oidc2461--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.29s)24622026/11/09 12:12:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50500/oidc2463--- PASS: TestValidateToken_Expired (0.33s)24642026/11/09 12:12:01 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:50486/oidc2465--- PASS: TestValidateToken_NoMatchingProvider (0.34s)24662026/11/09 12:12:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50505/oidc2467--- PASS: TestScopes_Rules (0.39s)24682026/11/09 12:12:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50507/oidc2469--- PASS: TestValidateToken_BoundSubjectMismatch (0.39s)24702026/11/09 12:12:01 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:50502/oidc24712026/11/09 12:12:01 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:50509/oidc2472--- PASS: TestValidateToken_MultipleProviders (0.47s)2473PASS2474Running hook tests...2475=== RUN TestSendPathsEmpty2476=== PAUSE TestSendPathsEmpty2477=== RUN TestQueueEnqueueAndFetch2478=== PAUSE TestQueueEnqueueAndFetch2479=== RUN TestQueueDeduplication2480=== PAUSE TestQueueDeduplication2481=== RUN TestQueueRemove2482=== PAUSE TestQueueRemove2483=== RUN TestQueueFetchBatchLimit2484=== PAUSE TestQueueFetchBatchLimit2485=== RUN TestQueueRetryMovesToBack2486=== PAUSE TestQueueRetryMovesToBack2487=== RUN TestQueueFetchRemoveLifecycle2488=== PAUSE TestQueueFetchRemoveLifecycle2489=== RUN TestQueueConcurrentWriters2490=== PAUSE TestQueueConcurrentWriters2491=== RUN TestQueueRemoveLargeClosure2492=== PAUSE TestQueueRemoveLargeClosure2493=== RUN TestServerClientIntegration2494--- PASS: TestServerClientIntegration (0.00s)2495=== RUN TestServerQueueError24962026/11/09 12:12:01 ERROR Failed to queue paths error="permission denied" count=12497--- PASS: TestServerQueueError (0.00s)2498=== RUN TestGetListenerSocketActivation2499 server_test.go:145: systemd socket activation does not exist on darwin2500--- SKIP: TestGetListenerSocketActivation (0.00s)2501=== RUN TestServerStalledClientDoesNotBlockShutdown2502=== PAUSE TestServerStalledClientDoesNotBlockShutdown2503=== RUN TestServerBacksOffOnAcceptErrors2504=== PAUSE TestServerBacksOffOnAcceptErrors2505=== RUN TestDrainIsolatesPoisonPath2506=== PAUSE TestDrainIsolatesPoisonPath2507=== RUN TestRunNotBlockedByPoisonHead2508=== PAUSE TestRunNotBlockedByPoisonHead2509=== RUN TestDrainGivesUpWhenServerDown2510=== PAUSE TestDrainGivesUpWhenServerDown2511=== RUN TestFailedPathPrunedByLaterClosure2512=== PAUSE TestFailedPathPrunedByLaterClosure2513=== RUN TestWorkerUploadsAndRemoves2514=== PAUSE TestWorkerUploadsAndRemoves2515=== RUN TestWorkerSkipsGCdPaths2516=== PAUSE TestWorkerSkipsGCdPaths2517=== RUN TestWorkerPrunesClosureDeps2518=== PAUSE TestWorkerPrunesClosureDeps2519=== RUN TestDrainTimeout2520=== PAUSE TestDrainTimeout2521=== RUN TestWorkerRemoveFailureIsNotProgress2522=== PAUSE TestWorkerRemoveFailureIsNotProgress2523=== RUN TestWorkerKeepsPathItCannotStat2524=== PAUSE TestWorkerKeepsPathItCannotStat2525=== CONT TestSendPathsEmpty2526=== CONT TestFailedPathPrunedByLaterClosure2527--- PASS: TestSendPathsEmpty (0.00s)2528=== CONT TestWorkerKeepsPathItCannotStat2529=== CONT TestWorkerRemoveFailureIsNotProgress2530=== CONT TestDrainTimeout2531=== CONT TestWorkerPrunesClosureDeps2532=== CONT TestWorkerSkipsGCdPaths2533=== CONT TestWorkerUploadsAndRemoves2534=== CONT TestDrainIsolatesPoisonPath2535=== CONT TestServerBacksOffOnAcceptErrors25362026/11/09 12:12:01 ERROR Accept failed error="too many open files"2537=== CONT TestServerStalledClientDoesNotBlockShutdown2538=== CONT TestQueueRemoveLargeClosure2539=== CONT TestQueueConcurrentWriters2540=== CONT TestQueueFetchRemoveLifecycle2541=== CONT TestQueueRetryMovesToBack2542=== CONT TestQueueDeduplication2543=== CONT TestQueueEnqueueAndFetch2544=== CONT TestQueueFetchBatchLimit2545=== CONT TestDrainGivesUpWhenServerDown2546=== CONT TestQueueRemove2547=== CONT TestRunNotBlockedByPoisonHead25482026/11/09 12:12:01 ERROR Accept failed error="too many open files"25492026/11/09 12:12:01 INFO Upload queue status pending=225502026/11/09 12:12:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestWorkerSkipsGCdPaths2189420686/002/nonexistent25512026/11/09 12:12:01 INFO Uploading batch count=125522026/11/09 12:12:01 ERROR Upload failed error="upload failed" count=12553--- PASS: TestQueueRetryMovesToBack (0.01s)25542026/11/09 12:12:01 INFO Uploading batch count=225552026/11/09 12:12:01 ERROR Upload failed error="upload failed" count=225562026/11/09 12:12:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestDrainGivesUpWhenServerDown4159053360/002/a25572026/11/09 12:12:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestWorkerRemoveFailureIsNotProgress3774849369/002/nonexistent25582026/11/09 12:12:01 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125592026/11/09 12:12:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestWorkerRemoveFailureIsNotProgress3774849369/002/nonexistent25602026/11/09 12:12:01 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125612026/11/09 12:12:01 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestWorkerRemoveFailureIsNotProgress3774849369/002/nonexistent25622026/11/09 12:12:01 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125632026/11/09 12:12:01 ERROR Drain finished with paths left in queue remaining=12564--- PASS: TestQueueDeduplication (0.01s)25652026/11/09 12:12:01 INFO Uploading batch count=12566--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25672026/11/09 12:12:01 INFO Upload queue status pending=325682026/11/09 12:12:01 INFO Uploading batch count=125692026/11/09 12:12:01 INFO Uploading batch count=12570--- PASS: TestQueueEnqueueAndFetch (0.01s)25712026/11/09 12:12:01 ERROR Upload failed error="upload failed" count=125722026/11/09 12:12:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestDrainGivesUpWhenServerDown4159053360/002/b25732026/11/09 12:12:01 INFO Uploading batch count=42574--- PASS: TestQueueFetchBatchLimit (0.01s)25752026/11/09 12:12:01 ERROR Upload failed error="upload failed" count=425762026/11/09 12:12:01 INFO Uploading batch count=225772026/11/09 12:12:01 INFO Upload queue status pending=225782026/11/09 12:12:01 INFO Uploading batch count=225792026/11/09 12:12:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestDrainIsolatesPoisonPath1249827186/002/bbb25802026/11/09 12:12:01 INFO Uploading batch count=125812026/11/09 12:12:01 INFO Upload queue status pending=225822026/11/09 12:12:01 ERROR Accept failed error="too many open files"2583--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25842026/11/09 12:12:01 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestWorkerKeepsPathItCannotStat2882207030/002/locked/aaa error="stat /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestWorkerKeepsPathItCannotStat2882207030/002/locked/aaa: permission denied"25852026/11/09 12:12:01 INFO Uploading batch count=125862026/11/09 12:12:01 INFO Uploading batch count=225872026/11/09 12:12:01 ERROR Upload failed error="upload failed" count=225882026/11/09 12:12:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestDrainGivesUpWhenServerDown4159053360/002/c2589--- PASS: TestQueueRemove (0.01s)25902026/11/09 12:12:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestDrainGivesUpWhenServerDown4159053360/002/d25912026/11/09 12:12:01 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestWorkerKeepsPathItCannotStat2882207030/002/locked/aaa error="stat /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestWorkerKeepsPathItCannotStat2882207030/002/locked/aaa: permission denied"25922026/11/09 12:12:01 INFO Uploading batch count=125932026/11/09 12:12:01 ERROR Upload failed error="upload failed" count=125942026/11/09 12:12:01 INFO Uploading batch count=225952026/11/09 12:12:01 ERROR Upload failed error="upload failed" count=225962026/11/09 12:12:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestDrainGivesUpWhenServerDown4159053360/002/e25972026/11/09 12:12:01 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestWorkerKeepsPathItCannotStat2882207030/002/locked/aaa error="stat /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestWorkerKeepsPathItCannotStat2882207030/002/locked/aaa: permission denied"25982026/11/09 12:12:01 INFO Uploading batch count=125992026/11/09 12:12:01 ERROR Upload failed error="upload failed" count=126002026/11/09 12:12:01 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestDrainGivesUpWhenServerDown4159053360/002/f26012026/11/09 12:12:01 ERROR Drain finished with paths left in queue remaining=126022026/11/09 12:12:01 ERROR Drain finished with paths left in queue remaining=1026032026/11/09 12:12:01 INFO Uploading batch count=126042026/11/09 12:12:01 ERROR Upload failed error="upload failed" count=12605--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)26062026/11/09 12:12:01 ERROR Drain finished with paths left in queue remaining=12607--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2608--- PASS: TestDrainIsolatesPoisonPath (0.02s)2609--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2610--- PASS: TestWorkerSkipsGCdPaths (0.03s)2611--- PASS: TestWorkerPrunesClosureDeps (0.03s)26122026/11/09 12:12:01 ERROR Accept failed error="too many open files"2613--- PASS: TestWorkerUploadsAndRemoves (0.04s)2614--- PASS: TestQueueConcurrentWriters (0.05s)2615--- PASS: TestQueueRemoveLargeClosure (0.07s)26162026/11/09 12:12:01 ERROR Accept failed error="too many open files"26172026/11/09 12:12:01 ERROR Accept failed error="too many open files"26182026/11/09 12:12:01 ERROR Failed to decode request error="read unix /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/hook1010178395/test.sock->: i/o timeout"26192026/11/09 12:12:01 ERROR Failed to write response error="write unix /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/hook1010178395/test.sock->: i/o timeout"2620--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26212026/11/09 12:12:01 ERROR Upload failed error="context deadline exceeded" count=226222026/11/09 12:12:01 ERROR Drain finished with paths left in queue remaining=42623--- PASS: TestDrainTimeout (0.22s)26242026/11/09 12:12:01 ERROR Accept failed error="too many open files"26252026/11/09 12:12:02 ERROR Accept failed error="too many open files"2626--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26272026/11/09 12:12:02 INFO Uploading batch count=126282026/11/09 12:12:02 INFO Uploading batch count=126292026/11/09 12:12:02 INFO Uploading batch count=126302026/11/09 12:12:02 ERROR Upload failed error="upload failed" count=126312026/11/09 12:12:02 INFO Uploading batch count=126322026/11/09 12:12:02 ERROR Upload failed error="upload failed" count=126332026/11/09 12:12:02 INFO Uploading batch count=126342026/11/09 12:12:02 ERROR Upload failed error="upload failed" count=126352026/11/09 12:12:02 INFO Uploading batch count=126362026/11/09 12:12:02 ERROR Upload failed error="upload failed" count=126372026/11/09 12:12:02 ERROR Drain finished with paths left in queue remaining=12638--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2639PASS2640Running signing tests...2641=== RUN TestExternalSigner2642=== PAUSE TestExternalSigner2643=== RUN TestExternalSignerWrongPublicKey2644=== PAUSE TestExternalSignerWrongPublicKey2645=== RUN TestExternalSignerErrors2646=== PAUSE TestExternalSignerErrors2647=== RUN TestExternalSignerRestartsAfterCrash2648=== PAUSE TestExternalSignerRestartsAfterCrash2649=== RUN TestExternalSignerProgramErrorKeepsProcess2650=== PAUSE TestExternalSignerProgramErrorKeepsProcess2651=== RUN TestExternalSignerClose2652=== PAUSE TestExternalSignerClose2653=== RUN TestExternalSignerRejectsInvalidPublicKey2654=== PAUSE TestExternalSignerRejectsInvalidPublicKey2655=== RUN TestExternalSignerCancellation2656=== PAUSE TestExternalSignerCancellation2657=== RUN TestGenerateFingerprint2658=== PAUSE TestGenerateFingerprint2659=== RUN TestParseSigningKey2660=== PAUSE TestParseSigningKey2661=== RUN TestSign2662=== PAUSE TestSign2663=== RUN TestSignBatch2664=== PAUSE TestSignBatch2665=== RUN TestNilKeyPublicKey2666=== PAUSE TestNilKeyPublicKey2667=== RUN TestSignErrors2668=== PAUSE TestSignErrors2669=== CONT TestExternalSigner2670=== CONT TestExternalSignerCancellation2671=== CONT TestExternalSignerProgramErrorKeepsProcess2672=== CONT TestExternalSignerRejectsInvalidPublicKey2673=== RUN TestExternalSignerRejectsInvalidPublicKey/#002674=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002675=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2676=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2677=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2678=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2679=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2680=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2681=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2682=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2683=== CONT TestExternalSignerRejectsInvalidPublicKey/#002684=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2685=== CONT TestExternalSignerClose2686=== CONT TestExternalSignerErrors2687=== RUN TestExternalSignerErrors/exit_at_startup2688=== PAUSE TestExternalSignerErrors/exit_at_startup2689=== RUN TestExternalSignerErrors/wrong_signature_length2690=== PAUSE TestExternalSignerErrors/wrong_signature_length2691=== RUN TestExternalSignerErrors/exit_on_request2692=== PAUSE TestExternalSignerErrors/exit_on_request2693=== RUN TestExternalSignerErrors/wrong_shape2694=== PAUSE TestExternalSignerErrors/wrong_shape2695=== RUN TestExternalSignerErrors/wrong_id2696=== CONT TestExternalSignerWrongPublicKey2697=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2698=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2699=== PAUSE TestExternalSignerErrors/wrong_id2700=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2701=== RUN TestExternalSignerErrors/missing_signatures2702--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2703 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2704 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2705 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2706 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2707 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2708=== CONT TestSignErrors2709=== CONT TestNilKeyPublicKey2710--- PASS: TestNilKeyPublicKey (0.00s)2711=== CONT TestParseSigningKey2712=== RUN TestParseSigningKey/valid_32-byte_key2713=== PAUSE TestParseSigningKey/valid_32-byte_key2714=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2715=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2716=== RUN TestParseSigningKey/no_colon2717=== PAUSE TestParseSigningKey/no_colon2718=== CONT TestSign2719=== CONT TestExternalSignerRestartsAfterCrash2720=== CONT TestGenerateFingerprint2721=== RUN TestParseSigningKey/empty_name2722=== RUN TestGenerateFingerprint/basic_with_references2723=== PAUSE TestParseSigningKey/empty_name2724=== RUN TestParseSigningKey/invalid_base642725=== CONT TestSignBatch2726=== PAUSE TestGenerateFingerprint/basic_with_references2727=== RUN TestGenerateFingerprint/no_references2728=== PAUSE TestGenerateFingerprint/no_references2729=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2730=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2731=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2732=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2733=== RUN TestGenerateFingerprint/invalid_nar_hash_length2734=== PAUSE TestExternalSignerErrors/missing_signatures2735=== PAUSE TestParseSigningKey/invalid_base642736=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2737=== RUN TestGenerateFingerprint/invalid_store_path_prefix2738=== RUN TestExternalSignerErrors/wrong_signatures_shape2739=== RUN TestParseSigningKey/wrong_length2740=== PAUSE TestParseSigningKey/wrong_length2741=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2742=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2743=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2744=== RUN TestExternalSignerErrors/too_few_signatures2745=== CONT TestParseSigningKey/valid_32-byte_key2746=== PAUSE TestExternalSignerErrors/too_few_signatures2747=== RUN TestExternalSignerErrors/missing_signature_name2748=== CONT TestParseSigningKey/wrong_length2749=== CONT TestParseSigningKey/invalid_base642750=== CONT TestParseSigningKey/empty_name2751=== CONT TestParseSigningKey/no_colon2752=== RUN TestGenerateFingerprint/invalid_reference_prefix2753=== PAUSE TestExternalSignerErrors/missing_signature_name2754=== RUN TestExternalSignerErrors/wrong_signature_name2755=== PAUSE TestExternalSignerErrors/wrong_signature_name2756=== RUN TestExternalSignerErrors/invalid_JSON2757=== PAUSE TestExternalSignerErrors/invalid_JSON2758=== RUN TestExternalSignerErrors/null2759=== PAUSE TestExternalSignerErrors/null2760=== RUN TestExternalSignerErrors/null_signatures2761=== PAUSE TestExternalSignerErrors/null_signatures2762=== RUN TestExternalSignerErrors/unrequested_key2763=== PAUSE TestExternalSignerErrors/unrequested_key2764=== RUN TestExternalSignerErrors/invalid_signature_base642765=== PAUSE TestExternalSignerErrors/invalid_signature_base642766=== RUN TestExternalSignerErrors/program_error2767=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2768=== CONT TestGenerateFingerprint/basic_with_references2769=== PAUSE TestExternalSignerErrors/program_error2770=== CONT TestGenerateFingerprint/invalid_reference_prefix2771=== CONT TestGenerateFingerprint/invalid_store_path_prefix2772=== CONT TestExternalSignerErrors/missing_signature_name2773=== CONT TestGenerateFingerprint/invalid_nar_hash_length2774=== CONT TestExternalSignerErrors/too_few_signatures2775=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2776=== CONT TestExternalSignerErrors/wrong_signatures_shape2777=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2778=== CONT TestExternalSignerErrors/missing_signatures2779=== CONT TestGenerateFingerprint/no_references2780--- PASS: TestGenerateFingerprint (0.00s)2781 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2782 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2783 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2784 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2785 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2786 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2787 --- PASS: TestGenerateFingerprint/no_references (0.00s)2788=== CONT TestExternalSignerErrors/exit_at_startup2789=== RUN TestSignErrors/nil_key2790=== PAUSE TestSignErrors/nil_key2791=== RUN TestSignErrors/nil_narinfo2792=== PAUSE TestSignErrors/nil_narinfo2793=== RUN TestSignErrors/invalid_narinfo2794=== CONT TestExternalSignerErrors/program_error2795=== CONT TestExternalSignerErrors/invalid_signature_base642796=== CONT TestExternalSignerErrors/unrequested_key2797=== CONT TestExternalSignerErrors/null_signatures2798=== CONT TestExternalSignerErrors/null2799=== CONT TestExternalSignerErrors/invalid_JSON2800=== CONT TestExternalSignerErrors/wrong_signature_name2801=== CONT TestExternalSignerErrors/wrong_id2802--- PASS: TestSign (0.00s)2803=== CONT TestExternalSignerErrors/wrong_shape2804=== PAUSE TestSignErrors/invalid_narinfo2805--- PASS: TestSignBatch (0.01s)2806=== CONT TestExternalSignerErrors/exit_on_request2807=== RUN TestSignErrors/canceled2808=== PAUSE TestSignErrors/canceled2809=== CONT TestExternalSignerErrors/wrong_signature_length2810=== CONT TestSignErrors/canceled2811=== CONT TestSignErrors/nil_key2812=== CONT TestSignErrors/invalid_narinfo2813--- PASS: TestParseSigningKey (0.00s)2814 --- PASS: TestParseSigningKey/wrong_length (0.00s)2815 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2816 --- PASS: TestParseSigningKey/empty_name (0.00s)2817 --- PASS: TestParseSigningKey/no_colon (0.00s)2818 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.01s)2819 --- PASS: TestParseSigningKey/valid_32-byte_key (0.01s)2820=== CONT TestSignErrors/nil_narinfo2821--- PASS: TestSignErrors (0.01s)2822 --- PASS: TestSignErrors/canceled (0.00s)2823 --- PASS: TestSignErrors/nil_key (0.00s)2824 --- PASS: TestSignErrors/nil_narinfo (0.00s)2825 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2826--- PASS: TestExternalSigner (0.26s)2827--- PASS: TestExternalSignerProgramErrorKeepsProcess (2.42s)2828--- PASS: TestExternalSignerWrongPublicKey (2.63s)2829--- PASS: TestExternalSignerCancellation (2.84s)2830--- PASS: TestExternalSignerClose (3.02s)2831--- PASS: TestExternalSignerRestartsAfterCrash (4.35s)2832/private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestExternalSignerRestartsAfterCrash1849321064/001/sign program: line 7: /private/var/tb/5/scratch/bdb5cbc18ba20a6b/build/TestExternalSignerRestartsAfterCrash1849321064/001/sign program.starts: No such file or directory2833--- PASS: TestExternalSignerErrors (0.00s)2834 --- PASS: TestExternalSignerErrors/missing_signature_name (0.43s)2835 --- PASS: TestExternalSignerErrors/unrequested_key (0.62s)2836 --- PASS: TestExternalSignerErrors/too_few_signatures (0.83s)2837 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.02s)2838 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.22s)2839 --- PASS: TestExternalSignerErrors/wrong_id (1.43s)2840 --- PASS: TestExternalSignerErrors/program_error (1.63s)2841 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.82s)2842 --- PASS: TestExternalSignerErrors/invalid_JSON (2.02s)2843 --- PASS: TestExternalSignerErrors/null_signatures (2.22s)2844 --- PASS: TestExternalSignerErrors/missing_signatures (3.21s)2845 --- PASS: TestExternalSignerErrors/exit_at_startup (3.50s)2846 --- PASS: TestExternalSignerErrors/wrong_signature_name (3.68s)2847 --- PASS: TestExternalSignerErrors/exit_on_request (3.89s)2848 --- PASS: TestExternalSignerErrors/wrong_shape (4.10s)2849 --- PASS: TestExternalSignerErrors/null (4.51s)2850PASS2851Running OpenBao signer tests...2852=== RUN TestSign2853=== PAUSE TestSign2854=== RUN TestSignErrors2855=== PAUSE TestSignErrors2856=== RUN TestServe2857=== PAUSE TestServe2858=== RUN TestServeRejectsGarbage2859=== PAUSE TestServeRejectsGarbage2860=== CONT TestSign2861=== CONT TestServe2862=== CONT TestServeRejectsGarbage2863--- PASS: TestServeRejectsGarbage (0.00s)2864=== CONT TestSignErrors2865=== RUN TestSignErrors/invalid_base642866=== PAUSE TestSignErrors/invalid_base642867=== RUN TestSignErrors/http_error2868=== PAUSE TestSignErrors/http_error2869=== RUN TestSignErrors/invalid_json2870=== PAUSE TestSignErrors/invalid_json2871=== RUN TestSignErrors/no_prefix2872=== PAUSE TestSignErrors/no_prefix2873=== CONT TestSignErrors/invalid_base642874=== CONT TestSignErrors/no_prefix2875=== CONT TestSignErrors/invalid_json2876--- PASS: TestServe (0.00s)2877=== CONT TestSignErrors/http_error2878--- PASS: TestSign (0.00s)2879--- PASS: TestSignErrors (0.00s)2880 --- PASS: TestSignErrors/invalid_json (0.00s)2881 --- PASS: TestSignErrors/http_error (0.00s)2882 --- PASS: TestSignErrors/no_prefix (0.00s)2883 --- PASS: TestSignErrors/invalid_base64 (0.00s)2884PASS