niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #474
· 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.11s)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 TestDoWithRetry_BodyReplayedViaGetBody114=== CONT TestDoServerRequestAttachesToken115=== CONT TestResolveStorePath116=== CONT TestScriptTokenEmptyCommand117--- PASS: TestScriptTokenEmptyCommand (0.00s)118=== CONT TestEncodeNixBase32WithRealHash119--- PASS: TestEncodeNixBase32WithRealHash (0.00s)120=== CONT TestEncodeNixBase32121=== RUN TestEncodeNixBase32/test_string_hash122=== CONT TestRegisterUploadedObject_OutlivesPush123=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer124=== CONT TestStreamPushStopsWhenCanceled125=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess126=== CONT TestScriptTokenScriptFails127=== CONT TestRateLimiterFeedback128=== CONT TestScriptTokenBadJSON129=== CONT TestScriptTokenEmptyToken130=== CONT TestPathInfoCACompatibility131=== CONT TestScriptTokenCachesUntilRefresh132=== CONT TestParsePathInfoJSONMultiplePaths133=== CONT TestScriptTokenNoExpiryRerunsEveryCall134=== CONT TestParsePathInfoJSON135=== CONT TestPathInfoHashCompatibility136=== CONT TestFileTokenEmpty137=== CONT TestFileTokenMissing138=== CONT TestGetStorePathHash139=== PAUSE TestEncodeNixBase32/test_string_hash140=== RUN TestEncodeNixBase32/empty_input141=== PAUSE TestEncodeNixBase32/empty_input142=== RUN TestGetStorePathHash/valid_store_path143=== PAUSE TestGetStorePathHash/valid_store_path144=== RUN TestGetStorePathHash/basename_without_hyphen_should_error145=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error146=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error147=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error148=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error149=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error150=== CONT TestDumpPathWriterError151--- PASS: TestStreamPushStopsWhenCanceled (0.00s)152=== CONT TestSetClientTLSErrors153=== CONT TestSetClientTLSDoesNotMutateDefaultTransport154=== CONT TestStaticToken1552026/11/09 12:15:38 WARN Rate limiter enabled after throttle name=server-test rate=5156--- PASS: TestStaticToken (0.00s)157=== CONT TestFileTokenReadsAndCaches158=== CONT TestConvertHashToNix32159=== CONT TestDumpPathSingleFile160=== RUN TestRateLimiterFeedback/429_enables_limiter161--- PASS: TestResolveStorePath (0.00s)162=== CONT TestSetClientTLS163=== RUN TestConvertHashToNix32/SRI_format_to_Nix32164=== RUN TestPathInfoCACompatibility/null_ca_field165=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths166=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths167=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths168--- PASS: TestFileTokenReadsAndCaches (0.01s)169=== CONT TestDumpPathMatchesNix170=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32171=== RUN TestConvertHashToNix32/already_Nix32_format172=== PAUSE TestConvertHashToNix32/already_Nix32_format173=== RUN TestConvertHashToNix32/invalid_format174--- PASS: TestScriptTokenScriptFails (0.01s)175=== CONT TestPartSizeForNAR176=== RUN TestPartSizeForNAR/zero_stays_at_minimum177=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum178=== RUN TestPartSizeForNAR/small_stays_at_minimum179=== PAUSE TestPartSizeForNAR/small_stays_at_minimum180=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum181=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)182=== RUN TestParsePathInfoJSON/Nix_format183--- PASS: TestFileTokenEmpty (0.00s)184=== CONT TestCaseHackSuffix185=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths186=== CONT TestUploadMultipart_ReturnsAfterDroppedBody187=== PAUSE TestPathInfoCACompatibility/null_ca_field188=== RUN TestPathInfoCACompatibility/old_string_format_-_text189=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text190=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive191=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive192=== RUN TestPathInfoCACompatibility/new_structured_format_-_text193=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text194=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method195=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method196=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum197=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts198=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts199=== RUN TestPartSizeForNAR/1_TiB200=== PAUSE TestPartSizeForNAR/1_TiB201=== RUN TestPartSizeForNAR/5_TiB_S3_max_object202=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object203=== RUN TestPartSizeForNAR/capped_at_5_GiB204=== PAUSE TestPartSizeForNAR/capped_at_5_GiB205=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun206=== CONT TestUploadMultipart_PartsInParallel207=== RUN TestSetClientTLSErrors/missing_cert_file208=== PAUSE TestSetClientTLSErrors/missing_cert_file209=== RUN TestSetClientTLSErrors/missing_key_file210=== PAUSE TestSetClientTLSErrors/missing_key_file211=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)212--- PASS: TestFileTokenMissing (0.01s)213=== PAUSE TestConvertHashToNix32/invalid_format214=== CONT TestFilterOversizedClosures215=== PAUSE TestRateLimiterFeedback/429_enables_limiter2162026/11/09 12:15:38 INFO Garbage collection started217--- PASS: TestRegisterUploadedObject_OutlivesPush (0.05s)218=== CONT TestRegisterUploadedObjectReusesConnections2192026/11/09 12:15:38 WARN Rate limiter enabled after throttle name=server-test rate=52202026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:514062212026/11/09 12:15:38 WARN Rate limiter backed off name=server-test rate=52222026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:51406223=== CONT TestStreamPushIsolatesFailures224=== RUN TestSetClientTLSErrors/missing_ca_file225=== PAUSE TestSetClientTLSErrors/missing_ca_file226=== RUN TestSetClientTLSErrors/invalid_ca_file227=== PAUSE TestSetClientTLSErrors/invalid_ca_file2282026/11/09 12:15:38 ERROR Upload failed error="bad path" count=3229=== CONT TestStreamPushReportsSkippedPaths230=== CONT TestStreamPushBatchesUnderLoad231=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false232=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false233=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true234=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true235=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry236=== CONT TestShellSplitErrors237=== CONT TestStreamPushReportsEveryPath238=== CONT TestStreamPushRequestLine239=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica240=== RUN TestFilterOversizedClosures/no_limit_keeps_everything241=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon2422026/11/09 12:15:38 ERROR Upload failed error=boom count=1243=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon244--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.03s)245--- PASS: TestDoServerRequestAttachesToken (0.05s)246=== RUN TestRateLimiterFeedback/503_enables_limiter247=== PAUSE TestRateLimiterFeedback/503_enables_limiter248=== CONT TestClientSignaturesByStorePath249=== CONT TestStreamPushReportsSignatures250=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter251=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter252=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter253=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter254=== CONT TestRetryTimeoutOutlastsMaxRetries255=== CONT TestStreamPushGivesUpOnDeadServer256=== CONT TestDoWithRetry_FinalResponseBodyReadable257=== PAUSE TestParsePathInfoJSON/Nix_format258=== CONT TestShellSplit259=== CONT TestEncodeNixBase32/test_string_hash260=== RUN TestParsePathInfoJSON/Lix_format261=== PAUSE TestParsePathInfoJSON/Lix_format262=== RUN TestParsePathInfoJSON/empty_input263=== PAUSE TestParsePathInfoJSON/empty_input264=== RUN TestParsePathInfoJSON/whitespace_only2652026/11/09 12:15:38 ERROR Upload failed error="connection refused" count=202662026/11/09 12:15:38 ERROR Server seems unavailable, giving up on batch untried=17267=== PAUSE TestParsePathInfoJSON/whitespace_only268=== RUN TestParsePathInfoJSON/invalid_JSON269=== PAUSE TestParsePathInfoJSON/invalid_JSON270=== CONT TestEncodeNixBase32/empty_input271=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error272=== CONT TestGetStorePathHash/basename_without_hyphen_should_error273=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths274=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error275=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI276=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI277=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512278=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512279=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths280=== CONT TestPartSizeForNAR/capped_at_5_GiB281=== CONT TestPartSizeForNAR/5_TiB_S3_max_object282=== CONT TestPartSizeForNAR/1_TiB283=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts284=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum285=== CONT TestPartSizeForNAR/small_stays_at_minimum286=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive287=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method288=== CONT TestPathInfoCACompatibility/new_structured_format_-_text289=== CONT TestPathInfoCACompatibility/old_string_format_-_text290=== CONT TestConvertHashToNix32/SRI_format_to_Nix32291=== CONT TestConvertHashToNix32/invalid_format292=== CONT TestConvertHashToNix32/already_Nix32_format293=== CONT TestSetClientTLSErrors/missing_cert_file294=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false295=== CONT TestPartSizeForNAR/zero_stays_at_minimum296=== CONT TestSetClientTLSErrors/missing_ca_file297=== CONT TestSetClientTLSErrors/invalid_ca_file2982026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:51491299=== CONT TestSetClientTLSErrors/missing_key_file300=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true301=== CONT TestGetStorePathHash/valid_store_path302=== CONT TestRateLimiterFeedback/429_enables_limiter303=== CONT TestPathInfoCACompatibility/null_ca_field304=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter305--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.03s)306--- PASS: TestStreamPushIsolatesFailures (0.01s)307--- PASS: TestStreamPushReportsSkippedPaths (0.00s)308--- PASS: TestShellSplitErrors (0.00s)309--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.06s)310--- PASS: TestStreamPushReportsEveryPath (0.00s)3112026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:51491312--- PASS: TestClientSignaturesByStorePath (0.00s)313--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.06s)314--- PASS: TestShellSplit (0.00s)315--- PASS: TestScriptTokenBadJSON (0.06s)316--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)3172026/11/09 12:15:38 WARN Rate limiter enabled after throttle name=server-test rate=53182026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:51495319=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything320=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped321=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped322=== RUN TestFilterOversizedClosures/all_closures_skipped323=== PAUSE TestFilterOversizedClosures/all_closures_skipped324--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)325 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)326 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)327=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter328=== CONT TestParsePathInfoJSON/Nix_format329=== CONT TestParsePathInfoJSON/whitespace_only3302026/11/09 12:15:38 WARN Rate limiter backed off name=server-test rate=5331=== CONT TestParsePathInfoJSON/invalid_JSON332=== CONT TestParsePathInfoJSON/Lix_format333=== CONT TestParsePathInfoJSON/empty_input334--- PASS: TestParsePathInfoJSON (0.05s)335 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)336 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)337 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)338 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)339 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)340=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)341=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512342=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI343=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon344--- PASS: TestPathInfoHashCompatibility (0.05s)345 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)346 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)347 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)348 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)349=== CONT TestFilterOversizedClosures/no_limit_keeps_everything3502026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:51491351=== CONT TestRateLimiterFeedback/503_enables_limiter352=== CONT TestFilterOversizedClosures/all_closures_skipped3532026/11/09 12:15:38 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50354=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3552026/11/09 12:15:38 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=2000356--- PASS: TestFilterOversizedClosures (0.03s)357 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)358 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)359 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)360--- PASS: TestConvertHashToNix32 (0.03s)361 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)362 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)363 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)364--- PASS: TestPartSizeForNAR (0.00s)365 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)366 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)367 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)368 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)369 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)370 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)371 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)3722026/11/09 12:15:38 ERROR Upload failed error=boom count=1373--- PASS: TestStreamPushReportsSignatures (0.01s)374--- PASS: TestScriptTokenEmptyToken (0.07s)375--- PASS: TestSetClientTLSErrors (0.06s)376 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)377 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)378 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)379 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)380--- PASS: TestGetStorePathHash (0.00s)381 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)382 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)383 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)384 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)385--- PASS: TestPathInfoCACompatibility (0.01s)386 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)387 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)388 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)389 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)390 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)391--- PASS: TestStreamPushBatchesUnderLoad (0.00s)392 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)393 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.01s)3942026/11/09 12:15:38 WARN Rate limiter enabled after throttle name=server-test rate=53952026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:51501396--- PASS: TestEncodeNixBase32 (0.00s)397 --- PASS: TestEncodeNixBase32/empty_input (0.00s)398 --- PASS: TestEncodeNixBase32/test_string_hash (0.01s)3992026/11/09 12:15:38 WARN Rate limiter backed off name=server-test rate=5400--- PASS: TestRateLimiterFeedback (0.06s)401 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)402 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)403 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)404 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)405=== RUN TestSetClientTLS/rejects_connection_without_client_cert4062026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:514914072026/11/09 12:15:38 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:51409/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:51409/api/uploads/complete4082026/11/09 12:15:38 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4092026/11/09 12:15:38 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:51409/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:51409/api/uploads/complete4102026/11/09 12:15:38 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"411=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert412=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA413=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA414=== RUN TestSetClientTLS/preserves_debug_logging_transport415=== PAUSE TestSetClientTLS/preserves_debug_logging_transport416=== CONT TestSetClientTLS/rejects_connection_without_client_cert4172026/11/09 12:15:38 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:51409/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:51409/api/uploads/complete4182026/11/09 12:15:38 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"419--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.13s)4202026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:514914212026/11/09 12:15:38 WARN Rate limiter enabled after throttle name=server-test rate=5422=== CONT TestSetClientTLS/preserves_debug_logging_transport423=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA4242026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:514884252026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:514914262026/11/09 12:15:38 WARN Rate limiter backed off name=server-test rate=5427--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.07s)4282026/11/09 12:15:38 INFO Garbage collection started4292026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:514914302026/11/09 12:15:38 WARN Rate limiter enabled after throttle name=s3-test rate=54312026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:51486432--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.09s)433--- PASS: TestStreamPushRequestLine (0.09s)4342026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:514914352026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:514914362026/11/09 12:15:38 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=04372026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:514914382026/11/09 12:15:38 WARN Garbage collection finished on another replica. Its statistics are not available here439--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.12s)4402026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:514914412026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:514914422026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:514914432026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:514914442026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:514914452026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:514914462026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:514914472026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:514914482026/11/09 12:15:38 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:514914492026/11/09 12:15:38 http: TLS handshake error from 127.0.0.1:51508: read tcp 127.0.0.1:51448->127.0.0.1:51508: use of closed network connection450--- PASS: TestSetClientTLS (0.11s)451 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.02s)452 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.05s)453 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.09s)454--- PASS: TestRegisterUploadedObjectReusesConnections (0.17s)455--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.21s)456--- PASS: TestDumpPathWriterError (0.22s)457--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.16s)458--- PASS: TestDumpPathSingleFile (0.22s)459--- PASS: TestScriptTokenCachesUntilRefresh (0.22s)460--- PASS: TestCaseHackSuffix (0.22s)461--- PASS: TestDumpPathMatchesNix (0.32s)462--- PASS: TestUploadMultipart_PartsInParallel (0.74s)463--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)464PASS465Running server tests...466The files belonging to this database system will be owned by user "_tribuchetbld1".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/1/scratch/7464b49615ad7d9a/build/postgres1796595838/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/1/scratch/7464b49615ad7d9a/build/postgres1796595838/data -l logfile start492493/private/var/tb/1/scratch/7464b49615ad7d9a/build/postgres1796595838:5432 - no response4942026-11-09 12:15:40.346 UTC [62293] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4952026-11-09 12:15:40.346 UTC [62293] LOG: listening on Unix socket "/private/var/tb/1/scratch/7464b49615ad7d9a/build/postgres1796595838/.s.PGSQL.5432"4962026-11-09 12:15:40.356 UTC [62307] LOG: database system was shut down at 2026-11-09 12:15:40 UTC4972026-11-09 12:15:40.358 UTC [62293] LOG: database system is ready to accept connections498/private/var/tb/1/scratch/7464b49615ad7d9a/build/postgres1796595838:5432 - accepting connections499{"timestamp":"2026-11-09T12:15:40.596807Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"4ddf7d0c-d515-4dbe-a57e-e567e90a13c1","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":10,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}500{"timestamp":"2026-11-09T12:15:40.713087Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"c7265514-a296-47d6-bbca-bf4d22c225cc","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:15:40.816675Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"cd5f7ccc-b980-497f-9373-74612d90ad70","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(9)"}502=== RUN TestAbortSucceeded503=== PAUSE TestAbortSucceeded504=== RUN TestService_AuthMiddleware505=== PAUSE TestService_AuthMiddleware506=== RUN TestService_AuthMiddleware_MTLSProxyHeader507=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader508=== RUN TestService_AuthMiddleware_MTLSBoundSubjects509=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects510=== RUN TestService_ReadAuthMiddleware511=== PAUSE TestService_ReadAuthMiddleware512=== RUN TestService_AuthMiddleware_OIDC513=== PAUSE TestService_AuthMiddleware_OIDC514=== RUN TestService_RequireScope_OIDC515=== PAUSE TestService_RequireScope_OIDC516=== RUN TestService_ReadScope_PublicByDefault517=== PAUSE TestService_ReadScope_PublicByDefault518=== RUN TestCacheConfigHandler519=== PAUSE TestCacheConfigHandler520=== RUN TestCacheStatsHandler521=== PAUSE TestCacheStatsHandler522=== RUN TestClientCADerivations523=== PAUSE TestClientCADerivations524=== RUN TestClientErrorHandling525=== PAUSE TestClientErrorHandling526=== RUN TestClientIntegration527=== PAUSE TestClientIntegration528=== RUN TestClientMultipleUploads529=== PAUSE TestClientMultipleUploads530=== RUN TestClientWithDependencies531=== PAUSE TestClientWithDependencies532=== RUN TestClientSharedPathCommittedMidPush533=== PAUSE TestClientSharedPathCommittedMidPush534=== RUN TestPinProtectsFromGC535=== PAUSE TestPinProtectsFromGC536=== RUN TestClientPushesUseOnePush537=== PAUSE TestClientPushesUseOnePush538=== RUN TestClientFallsBackToClosures539=== PAUSE TestClientFallsBackToClosures540=== RUN TestDeleteClosuresRacingPins541=== PAUSE TestDeleteClosuresRacingPins542=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock543=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock544=== RUN TestResolveDBConnectionString545=== PAUSE TestResolveDBConnectionString546=== RUN TestConnectWaitsForAPeerMigration547=== PAUSE TestConnectWaitsForAPeerMigration548=== RUN TestLeadElectsOneAndHandsOver549=== PAUSE TestLeadElectsOneAndHandsOver550=== RUN TestLeadIncumbentWinsAfterRestart5512026/11/09 12:15:41 INFO lead: acquired remote=192.0.2.1:12345522026/11/09 12:15:41 INFO lead: released remote=192.0.2.1:12345532026/11/09 12:15:41 INFO lead: acquired remote=192.0.2.1:12345542026/11/09 12:15:42 INFO lead: released remote=192.0.2.1:1234555--- PASS: TestLeadIncumbentWinsAfterRestart (2.05s)556=== RUN TestLeadIncumbentAnnouncesAtOnce557=== PAUSE TestLeadIncumbentAnnouncesAtOnce558=== RUN TestLeadEndsOnShutdown559=== PAUSE TestLeadEndsOnShutdown560=== RUN TestLeadEndsWhenItsConnectionHangs5612026/11/09 12:15:43 INFO lead: acquired remote=192.0.2.1:12345622026-11-09 12:15:44.569 UTC [62353] FATAL: terminating connection due to administrator command5632026/11/09 12:15:44 INFO lead: acquired remote=192.0.2.1:12345642026/11/09 12:15:45 WARN lead: lock connection lost error="timeout: context deadline exceeded"5652026/11/09 12:15:45 INFO lead: released remote=192.0.2.1:12345662026/11/09 12:15:45 INFO lead: released remote=192.0.2.1:1234567--- PASS: TestLeadEndsWhenItsConnectionHangs (3.00s)568=== RUN TestGCAdvisoryLockBlocksConcurrentRun569=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun570=== RUN TestGCBugBareHashReferences571=== PAUSE TestGCBugBareHashReferences572=== RUN TestGCMetrics573=== PAUSE TestGCMetrics574=== RUN TestPushDedupSurvivesConcurrentGC575=== PAUSE TestPushDedupSurvivesConcurrentGC576=== RUN TestDeduplicatedObjectsRecordedAsPending577=== PAUSE TestDeduplicatedObjectsRecordedAsPending578=== RUN TestGCSweepSkipsPendingObjects579=== PAUSE TestGCSweepSkipsPendingObjects580=== RUN TestTombstonedObjectOfferedWithoutWaiting581=== PAUSE TestTombstonedObjectOfferedWithoutWaiting582=== RUN TestGCSweepDeliversEachKeyOnce583=== PAUSE TestGCSweepDeliversEachKeyOnce584=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection585=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection586=== RUN TestForceGCDuringPushOffersSweptObject587=== PAUSE TestForceGCDuringPushOffersSweptObject588=== RUN TestFailedS3DeleteKeepsTombstone589=== PAUSE TestFailedS3DeleteKeepsTombstone590=== RUN TestSweepSkipsRowsLockedByPush591=== PAUSE TestSweepSkipsRowsLockedByPush592=== RUN TestRegisterCompletedObjectNeedsPendingRow593=== PAUSE TestRegisterCompletedObjectNeedsPendingRow594=== RUN TestGetExistingObjectsLocksRows595=== PAUSE TestGetExistingObjectsLocksRows596=== RUN TestSweepRechecksPendingAfterLocking597=== PAUSE TestSweepRechecksPendingAfterLocking598=== RUN TestPushWaitsForSweepHoldingRow599=== PAUSE TestPushWaitsForSweepHoldingRow600=== RUN TestCommitRacingPendingCleanupKeepsObjects601=== PAUSE TestCommitRacingPendingCleanupKeepsObjects602=== RUN TestGCEndsOnShutdown603=== PAUSE TestGCEndsOnShutdown604=== RUN TestGCTaskStore_StartNew605=== PAUSE TestGCTaskStore_StartNew606=== RUN TestGCTaskStore_DeduplicateSameParams607=== PAUSE TestGCTaskStore_DeduplicateSameParams608=== RUN TestGCTaskStore_ConflictDifferentParams609=== PAUSE TestGCTaskStore_ConflictDifferentParams610=== RUN TestGCTaskStore_GetEmpty611=== PAUSE TestGCTaskStore_GetEmpty612=== RUN TestGCTaskStore_GetReturnsLatest613=== PAUSE TestGCTaskStore_GetReturnsLatest614=== RUN TestGCTaskStore_CompletedAllowsNewTask615=== PAUSE TestGCTaskStore_CompletedAllowsNewTask616=== RUN TestGCTaskStore_PhaseUpdates617=== PAUSE TestGCTaskStore_PhaseUpdates618=== RUN TestGCTaskStore_Fail619=== PAUSE TestGCTaskStore_Fail620=== RUN TestGracefulShutdownDrainsInflight621=== PAUSE TestGracefulShutdownDrainsInflight622=== RUN TestService_healthCheckHandler623=== PAUSE TestService_healthCheckHandler624=== RUN TestService_readinessHandler625=== PAUSE TestService_readinessHandler626=== RUN TestGenerateLandingPage627=== PAUSE TestGenerateLandingPage628=== RUN TestEnsureAbortUploadsRule629=== PAUSE TestEnsureAbortUploadsRule630=== RUN TestCacheConfigHandlerMaxNarSize631=== PAUSE TestCacheConfigHandlerMaxNarSize632=== RUN TestCreatePendingClosureRejectsOversizedNAR633=== PAUSE TestCreatePendingClosureRejectsOversizedNAR634=== RUN TestNARDeduplicationMetadataUploadBug635=== PAUSE TestNARDeduplicationMetadataUploadBug636=== RUN TestMetricsInventory637=== PAUSE TestMetricsInventory638=== RUN TestMetricsCommit639=== PAUSE TestMetricsCommit640=== RUN TestService_NativeMTLS641=== PAUSE TestService_NativeMTLS642=== RUN TestServerTLSConfig643=== PAUSE TestServerTLSConfig644=== RUN TestMultipartCleanup645=== PAUSE TestMultipartCleanup646=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded647=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded648=== RUN TestPendingCleanupUsesOneCutoff649=== PAUSE TestPendingCleanupUsesOneCutoff650=== RUN TestObjectStatsTrigger651=== PAUSE TestObjectStatsTrigger652=== RUN TestObjectStatsUpdatedOncePerCommit653=== PAUSE TestObjectStatsUpdatedOncePerCommit654=== RUN TestOrphanedObjectsGC655=== PAUSE TestOrphanedObjectsGC656=== RUN TestOrphanedObjectsGCStressTest657=== PAUSE TestOrphanedObjectsGCStressTest658=== RUN TestCreatePin_ReservedPins659=== PAUSE TestCreatePin_ReservedPins660=== RUN TestPresentReportsOnlyClosureRoots661=== PAUSE TestPresentReportsOnlyClosureRoots662=== RUN TestPresentRefreshesOnlyStaleClosures663=== PAUSE TestPresentRefreshesOnlyStaleClosures664=== RUN TestPresentNotReportedWhileGCDeletesClosure665=== PAUSE TestPresentNotReportedWhileGCDeletesClosure666=== RUN TestParseSingleRange667=== PAUSE TestParseSingleRange668=== RUN TestProxyHeadersOnlyTrustedOnSocket6692026/11/09 12:15:46 INFO Starting HTTP server address=127.0.0.1:515386702026/11/09 12:15:46 INFO Starting HTTP server address=proxy.sock6712026/11/09 12:15:46 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6722026/11/09 12:15:46 INFO Shutdown signal received, draining in-flight requests timeout=10s673--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.20s)674=== RUN TestIsValidCachePath675=== PAUSE TestIsValidCachePath676=== RUN TestReadProxyNarinfo677=== PAUSE TestReadProxyNarinfo678=== RUN TestReadProxyNarinfoAlreadyDecompressed679=== PAUSE TestReadProxyNarinfoAlreadyDecompressed680=== RUN TestReadProxyContentNegotiation681=== PAUSE TestReadProxyContentNegotiation682=== RUN TestReadProxyNarStreaming683=== PAUSE TestReadProxyNarStreaming684=== RUN TestReadProxy404685=== PAUSE TestReadProxy404686=== RUN TestReadProxyInvalidPath687=== PAUSE TestReadProxyInvalidPath688=== RUN TestReadProxyHead689=== PAUSE TestReadProxyHead690=== RUN TestReadProxyOutlastsServerWriteTimeout691=== PAUSE TestReadProxyOutlastsServerWriteTimeout692=== RUN TestReadProxyConditionalGet693=== PAUSE TestReadProxyConditionalGet694=== RUN TestReadProxyRootRedirectsToIndexHTML695=== PAUSE TestReadProxyRootRedirectsToIndexHTML696=== RUN TestReadProxyDisabled697=== PAUSE TestReadProxyDisabled698=== RUN TestReadRedirectNar699=== PAUSE TestReadRedirectNar700=== RUN TestReadRedirectKeepsNarinfoProxied701=== PAUSE TestReadRedirectKeepsNarinfoProxied702=== RUN TestReadProxyRangeRequest703=== PAUSE TestReadProxyRangeRequest704=== RUN TestReadRedirectUsesPublicS3URL705=== PAUSE TestReadRedirectUsesPublicS3URL706=== RUN TestPush_OverlappingRootsStoreOneRowPerKey707=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey708=== RUN TestPush_CompleteCommitsEveryRoot709=== PAUSE TestPush_CompleteCommitsEveryRoot710=== RUN TestPush_RepeatedRootCommitsOnce711=== PAUSE TestPush_RepeatedRootCommitsOnce712=== RUN TestPush_CompleteWaitsForCleanupOfThePush713=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush714=== RUN TestPush_RootsAreLockedInByteOrder715=== PAUSE TestPush_RootsAreLockedInByteOrder716=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit717=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit718=== RUN TestPush_RejectsBadRequests719=== PAUSE TestPush_RejectsBadRequests720=== RUN TestPush_SignsNarinfosOfItsPendingObjects721=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects722=== RUN TestSharedNarBothUploadsComplete723=== PAUSE TestSharedNarBothUploadsComplete724=== RUN TestCompleteMultipartUpload_ErrorButObjectExists725=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists726=== RUN TestCompletedNarNotReofferedAcrossClosures727=== PAUSE TestCompletedNarNotReofferedAcrossClosures728=== RUN TestPresignedUploadRegisteredBeforeCommit729=== PAUSE TestPresignedUploadRegisteredBeforeCommit730=== RUN TestService_Rustfstest731=== PAUSE TestService_Rustfstest732=== RUN TestParseSize733=== PAUSE TestParseSize734=== RUN TestSkippedUploadsHandler735=== PAUSE TestSkippedUploadsHandler736=== RUN TestSystemdListenerNotActivated737--- PASS: TestSystemdListenerNotActivated (0.00s)738=== RUN TestWatchdogBeatsWhenHealthy739--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)740=== RUN TestWatchdogSkipsWhenUnhealthy7412026/11/09 12:15:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7422026/11/09 12:15:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7432026/11/09 12:15:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7442026/11/09 12:15:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7452026/11/09 12:15:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/09 12:15:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/09 12:15:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7482026/11/09 12:15:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7492026/11/09 12:15:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7502026/11/09 12:15:46 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"751--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)752=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle753=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle754=== RUN TestProxyWriteTimeout755=== PAUSE TestProxyWriteTimeout756=== RUN TestPendingClosureWriteTimeout757=== PAUSE TestPendingClosureWriteTimeout758=== RUN TestIsValidUploadKey759=== PAUSE TestIsValidUploadKey760=== RUN TestUploadHandlersRejectInvalidKeys761=== PAUSE TestUploadHandlersRejectInvalidKeys762=== RUN TestUploadHandlersRejectOversizedBody763=== PAUSE TestUploadHandlersRejectOversizedBody764=== RUN TestService_cleanupPendingClosuresHandler765=== PAUSE TestService_cleanupPendingClosuresHandler766=== RUN TestService_createPendingClosureHandler767=== PAUSE TestService_createPendingClosureHandler768=== RUN TestService_verifyS3Integrity769=== PAUSE TestService_verifyS3Integrity770=== RUN TestService_verifyS3ReuploadsStaleNarinfo771=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo772=== RUN TestCompleteMultipartUnregistered773=== PAUSE TestCompleteMultipartUnregistered774=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT775=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT776=== CONT TestPush_RootsAreLockedInByteOrder777=== CONT TestService_NativeMTLS778=== CONT TestGCTaskStore_DeduplicateSameParams779--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)780=== CONT TestGCTaskStore_GetEmpty781--- PASS: TestGCTaskStore_GetEmpty (0.00s)782=== CONT TestServerTLSConfig783=== CONT TestGCTaskStore_GetReturnsLatest784=== RUN TestServerTLSConfig/no_client_CA785--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)786=== PAUSE TestServerTLSConfig/no_client_CA787=== CONT TestReadProxyNarStreaming788=== CONT TestReadProxyContentNegotiation789=== CONT TestPush_CompleteWaitsForCleanupOfThePush790=== CONT TestPush_RepeatedRootCommitsOnce791=== CONT TestPush_CompleteCommitsEveryRoot792=== CONT TestPush_OverlappingRootsStoreOneRowPerKey793=== CONT TestReadRedirectUsesPublicS3URL794=== CONT TestReadProxyRangeRequest795=== CONT TestReadRedirectKeepsNarinfoProxied796=== CONT TestReadRedirectNar797=== CONT TestReadProxyDisabled798=== CONT TestReadProxyRootRedirectsToIndexHTML799=== CONT TestReadProxyConditionalGet800=== CONT TestReadProxyOutlastsServerWriteTimeout801=== CONT TestReadProxyHead802=== CONT TestReadProxyInvalidPath803=== CONT TestMultipartCleanup804=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded805=== CONT TestAbortSucceeded806--- PASS: TestAbortSucceeded (0.00s)807=== CONT TestReadProxy404808=== CONT TestGCTaskStore_ConflictDifferentParams809--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)810=== RUN TestServerTLSConfig/missing_CA_file811=== PAUSE TestServerTLSConfig/missing_CA_file812=== RUN TestServerTLSConfig/not_a_PEM_file813=== CONT TestReadProxyNarinfoAlreadyDecompressed814=== PAUSE TestServerTLSConfig/not_a_PEM_file815=== CONT TestGCTaskStore_StartNew816=== CONT TestReadProxyNarinfo817--- PASS: TestGCTaskStore_StartNew (0.00s)818=== CONT TestGCEndsOnShutdown819=== RUN TestGCEndsOnShutdown/before_the_run820=== PAUSE TestGCEndsOnShutdown/before_the_run821=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete822=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete823=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark824=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark825=== CONT TestIsValidCachePath826=== RUN TestIsValidCachePath/narinfo827=== PAUSE TestIsValidCachePath/narinfo828=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars829=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars830=== RUN TestIsValidCachePath/nar_zst831=== PAUSE TestIsValidCachePath/nar_zst832=== RUN TestIsValidCachePath/nar_xz833=== PAUSE TestIsValidCachePath/nar_xz834=== RUN TestIsValidCachePath/nar_bz2835=== PAUSE TestIsValidCachePath/nar_bz2836=== RUN TestIsValidCachePath/nar_uncompressed837=== PAUSE TestIsValidCachePath/nar_uncompressed838=== RUN TestIsValidCachePath/ls839=== PAUSE TestIsValidCachePath/ls840=== RUN TestIsValidCachePath/log841=== PAUSE TestIsValidCachePath/log842=== RUN TestIsValidCachePath/realisation843=== PAUSE TestIsValidCachePath/realisation844=== RUN TestIsValidCachePath/nix-cache-info845=== PAUSE TestIsValidCachePath/nix-cache-info846=== RUN TestIsValidCachePath/index.html847=== PAUSE TestIsValidCachePath/index.html848=== RUN TestIsValidCachePath/traversal_parent849=== PAUSE TestIsValidCachePath/traversal_parent850=== RUN TestIsValidCachePath/traversal_in_middle851=== PAUSE TestIsValidCachePath/traversal_in_middle852=== RUN TestIsValidCachePath/invalid_char_e853=== PAUSE TestIsValidCachePath/invalid_char_e854=== RUN TestIsValidCachePath/invalid_char_u855=== PAUSE TestIsValidCachePath/invalid_char_u856=== RUN TestIsValidCachePath/random_path857=== PAUSE TestIsValidCachePath/random_path858=== RUN TestIsValidCachePath/empty859=== PAUSE TestIsValidCachePath/empty860=== RUN TestIsValidCachePath/leading_slash861=== PAUSE TestIsValidCachePath/leading_slash862=== RUN TestIsValidCachePath/wrong_extension863=== PAUSE TestIsValidCachePath/wrong_extension864=== RUN TestIsValidCachePath/short_hash865=== PAUSE TestIsValidCachePath/short_hash866=== CONT TestParseSingleRange867=== RUN TestParseSingleRange/none868=== PAUSE TestParseSingleRange/none869=== RUN TestParseSingleRange/unknown_unit870=== PAUSE TestParseSingleRange/unknown_unit871=== RUN TestParseSingleRange/multi-range_ignored872=== PAUSE TestParseSingleRange/multi-range_ignored873=== RUN TestParseSingleRange/malformed_no_dash874=== PAUSE TestParseSingleRange/malformed_no_dash875=== RUN TestParseSingleRange/malformed_both_empty876=== PAUSE TestParseSingleRange/malformed_both_empty877=== RUN TestParseSingleRange/malformed_end_before_start878=== PAUSE TestParseSingleRange/malformed_end_before_start879=== RUN TestParseSingleRange/closed880=== PAUSE TestParseSingleRange/closed881=== RUN TestParseSingleRange/open-ended882=== PAUSE TestParseSingleRange/open-ended883=== RUN TestParseSingleRange/end_clamped_to_size884=== PAUSE TestParseSingleRange/end_clamped_to_size885=== RUN TestParseSingleRange/suffix886=== PAUSE TestParseSingleRange/suffix887=== RUN TestParseSingleRange/suffix_exceeds_size888=== PAUSE TestParseSingleRange/suffix_exceeds_size889=== RUN TestParseSingleRange/single_byte890=== PAUSE TestParseSingleRange/single_byte891=== RUN TestParseSingleRange/start_past_EOF892=== PAUSE TestParseSingleRange/start_past_EOF893=== RUN TestParseSingleRange/start_far_past_EOF894=== PAUSE TestParseSingleRange/start_far_past_EOF895=== CONT TestCommitRacingPendingCleanupKeepsObjects896--- PASS: TestReadProxyNarStreaming (1.58s)897=== CONT TestPresentNotReportedWhileGCDeletesClosure898=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale899=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale900=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh901=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh902=== CONT TestPushWaitsForSweepHoldingRow9032026/11/09 12:15:48 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9042026/11/09 12:15:48 WARN mTLS auth: subject not in bound subjects subject="CN=reader"905--- PASS: TestService_NativeMTLS (1.80s)906=== CONT TestPresentRefreshesOnlyStaleClosures9072026/11/09 12:15:48 INFO Received push request method=POST path=/api/pushes9082026-11-09 12:15:48.824 UTC [62466] ERROR: could not obtain lock on row in relation "closures"9092026-11-09 12:15:48.824 UTC [62466] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9102026-11-09 12:15:48.825 UTC [62466] ERROR: could not obtain lock on row in relation "closures"9112026-11-09 12:15:48.825 UTC [62466] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9122026-11-09 12:15:48.828 UTC [62466] ERROR: could not obtain lock on row in relation "closures"9132026-11-09 12:15:48.828 UTC [62466] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9142026-11-09 12:15:48.837 UTC [62466] ERROR: could not obtain lock on row in relation "closures"9152026-11-09 12:15:48.837 UTC [62466] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT9162026-11-09 12:15:48.839 UTC [62466] ERROR: could not obtain lock on row in relation "closures"9172026-11-09 12:15:48.839 UTC [62466] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT918--- PASS: TestPush_RootsAreLockedInByteOrder (2.48s)919=== CONT TestSweepRechecksPendingAfterLocking9202026/11/09 12:15:49 INFO Received push request method=POST path=/api/pushes9212026/11/09 12:15:49 INFO Received complete push request method=POST path=/api/pushes/1/complete9222026/11/09 12:15:49 INFO Completed push id=1 objects=4 duration=51.455958ms923--- PASS: TestPush_RepeatedRootCommitsOnce (2.79s)924=== CONT TestGetExistingObjectsLocksRows925--- PASS: TestReadProxyContentNegotiation (4.17s)926=== CONT TestPresentReportsOnlyClosureRoots9272026/11/09 12:15:51 INFO Aborted multipart uploads count=0 kept=09282026/11/09 12:15:51 WARN Force mode enabled - objects will be deleted immediately without grace period9292026/11/09 12:15:51 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=09302026/11/09 12:15:51 INFO Vacuumed table table=pending_closures9312026/11/09 12:15:51 INFO Vacuumed table table=pending_objects9322026/11/09 12:15:51 INFO Vacuumed table table=multipart_uploads9332026/11/09 12:15:51 INFO Vacuumed table table=closures9342026/11/09 12:15:51 INFO Received push request method=POST path=/api/pushes9352026/11/09 12:15:51 INFO Vacuumed table table=objects936--- PASS: TestCommitRacingPendingCleanupKeepsObjects (4.85s)937=== CONT TestCreatePin_ReservedPins9382026/11/09 12:15:51 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51572/oidc939--- PASS: TestReadProxyInvalidPath (5.19s)940=== CONT TestRegisterCompletedObjectNeedsPendingRow9412026-11-09 12:15:51.649 UTC [62504] ERROR: Push does not exist: id=19422026-11-09 12:15:51.649 UTC [62504] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE9432026-11-09 12:15:51.649 UTC [62504] STATEMENT: SELECT commit_push($1)944--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (5.23s)945=== CONT TestSweepSkipsRowsLockedByPush946--- PASS: TestReadProxyDisabled (5.56s)947=== CONT TestFailedS3DeleteKeepsTombstone9482026/11/09 12:15:52 INFO Received push request method=POST path=/api/pushes9492026/11/09 12:15:52 INFO Received complete push request method=POST path=/api/pushes/1/complete9502026/11/09 12:15:52 INFO Completed push id=1 objects=6 duration=57.913ms951--- PASS: TestPush_CompleteCommitsEveryRoot (5.98s)952=== CONT TestForceGCDuringPushOffersSweptObject953=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows954=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows955=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check956=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check957=== CONT TestOrphanedObjectsGCStressTest958--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.14s)959=== CONT TestOrphanedObjectsGC960--- PASS: TestReadProxyHead (6.61s)961=== CONT TestObjectStatsUpdatedOncePerCommit962--- PASS: TestReadProxyNarinfoAlreadyDecompressed (7.05s)963=== CONT TestObjectStatsTrigger964--- PASS: TestReadRedirectNar (7.63s)965=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection9662026/11/09 12:15:54 INFO Received uploads request method=POST path=/api/pending_closures9672026/11/09 12:15:54 INFO Received cleanup request method=DELETE path=/api/pending_closures9682026/11/09 12:15:54 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket19/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""9692026/11/09 12:15:54 INFO Aborted multipart uploads count=0 kept=19702026/11/09 12:15:54 INFO Received cleanup request method=DELETE path=/api/pending_closures9712026/11/09 12:15:54 INFO Aborted multipart uploads count=1 kept=0972--- PASS: TestMultipartCleanup (8.35s)973=== CONT TestPendingCleanupUsesOneCutoff974--- PASS: TestReadRedirectKeepsNarinfoProxied (8.49s)975=== CONT TestGCSweepDeliversEachKeyOnce976--- PASS: TestReadProxyRangeRequest (8.94s)977=== CONT TestTombstonedObjectOfferedWithoutWaiting9782026/11/09 12:15:55 INFO Received uploads request method=POST path=/api/pending_closures979--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (9.34s)980=== CONT TestPinProtectsFromGC981--- PASS: TestReadRedirectUsesPublicS3URL (9.64s)982=== CONT TestClientSharedPathCommittedMidPush9832026/11/09 12:15:56 INFO Received push request method=POST path=/api/pushes984--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (10.09s)985=== CONT TestGCSweepSkipsPendingObjects9862026/11/09 12:15:56 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>987--- PASS: TestReadProxyNarinfo (10.44s)988=== CONT TestClientWithDependencies989--- PASS: TestReadProxyConditionalGet (11.06s)990=== CONT TestClientMultipleUploads991--- PASS: TestReadProxy404 (11.40s)992=== CONT TestDeduplicatedObjectsRecordedAsPending993--- PASS: TestPresentRefreshesOnlyStaleClosures (9.66s)994=== CONT TestPushDedupSurvivesConcurrentGC995--- PASS: TestReadProxyOutlastsServerWriteTimeout (11.56s)996=== CONT TestGCMetrics9972026/11/09 12:15:58 INFO Received uploads request method=POST path=/api/pending_closures9982026/11/09 12:15:58 INFO Aborted multipart uploads count=0 kept=0999--- PASS: TestPushWaitsForSweepHoldingRow (10.76s)1000=== CONT TestClientIntegration10012026/11/09 12:15:58 WARN Force mode enabled - objects will be deleted immediately without grace period10022026/11/09 12:15:58 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010032026/11/09 12:15:58 INFO Vacuumed table table=pending_closures10042026/11/09 12:15:58 INFO Vacuumed table table=pending_objects10052026/11/09 12:15:58 INFO Vacuumed table table=multipart_uploads10062026/11/09 12:15:58 INFO Vacuumed table table=closures10072026/11/09 12:15:58 INFO Vacuumed table table=objects1008--- PASS: TestSweepRechecksPendingAfterLocking (10.02s)1009=== CONT TestGCBugBareHashReferences1010--- PASS: TestGetExistingObjectsLocksRows (9.83s)1011=== CONT TestClientErrorHandling1012=== RUN TestClientErrorHandling/InvalidStorePath1013=== PAUSE TestClientErrorHandling/InvalidStorePath1014=== RUN TestClientErrorHandling/InvalidAuthToken1015=== PAUSE TestClientErrorHandling/InvalidAuthToken1016=== RUN TestClientErrorHandling/ServerNotAvailable1017=== PAUSE TestClientErrorHandling/ServerNotAvailable1018=== CONT TestClientCADerivations1019--- PASS: TestPresentReportsOnlyClosureRoots (8.73s)1020=== CONT TestCacheStatsHandler10212026/11/09 12:15:59 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10222026/11/09 12:15:59 WARN Refused reserved pin name=worker-x86_64-linux10232026/11/09 12:15:59 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux10242026/11/09 12:15:59 INFO Received create pin request method=POST path=/api/pins/my-app10252026/11/09 12:15:59 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1026--- PASS: TestCreatePin_ReservedPins (8.30s)1027=== CONT TestCacheConfigHandler1028=== RUN TestCacheConfigHandler/full_config,_no_issuer1029=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1030=== RUN TestCacheConfigHandler/no_cache_url_configured1031=== PAUSE TestCacheConfigHandler/no_cache_url_configured1032=== RUN TestCacheConfigHandler/no_signing_keys1033=== PAUSE TestCacheConfigHandler/no_signing_keys1034=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1035=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1036=== CONT TestGCAdvisoryLockBlocksConcurrentRun10372026/11/09 12:16:00 INFO Aborted multipart uploads count=0 kept=010382026/11/09 12:16:00 WARN Force mode enabled - objects will be deleted immediately without grace period10392026/11/09 12:16:00 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=010402026/11/09 12:16:00 INFO Vacuumed table table=pending_closures10412026/11/09 12:16:00 INFO Vacuumed table table=pending_objects10422026/11/09 12:16:00 INFO Vacuumed table table=multipart_uploads10432026/11/09 12:16:00 INFO Vacuumed table table=closures10442026/11/09 12:16:00 INFO Vacuumed table table=objects10452026/11/09 12:16:00 INFO Aborted multipart uploads count=0 kept=010462026/11/09 12:16:00 WARN Force mode enabled - objects will be deleted immediately without grace period1047--- PASS: TestRegisterCompletedObjectNeedsPendingRow (8.85s)1048=== CONT TestService_ReadScope_PublicByDefault10492026/11/09 12:16:00 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=010502026/11/09 12:16:00 INFO Vacuumed table table=pending_closures10512026/11/09 12:16:00 INFO Vacuumed table table=pending_objects10522026/11/09 12:16:00 INFO Vacuumed table table=multipart_uploads10532026/11/09 12:16:00 INFO Vacuumed table table=closures10542026/11/09 12:16:00 INFO Vacuumed table table=objects1055--- PASS: TestSweepSkipsRowsLockedByPush (8.97s)1056=== CONT TestService_RequireScope_OIDC10572026/11/09 12:16:00 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51671/oidc10582026/11/09 12:16:00 INFO Received uploads request method=POST path=/api/pending_closures10592026/11/09 12:16:00 INFO Aborted multipart uploads count=0 kept=010602026/11/09 12:16:01 WARN Force mode enabled - objects will be deleted immediately without grace period10612026/11/09 12:16:01 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."10622026/11/09 12:16:01 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1063--- PASS: TestFailedS3DeleteKeepsTombstone (9.05s)1064=== CONT TestService_AuthMiddleware_OIDC10652026/11/09 12:16:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51681/oidc1066--- PASS: TestObjectStatsUpdatedOncePerCommit (8.73s)1067=== CONT TestService_ReadAuthMiddleware1068--- PASS: TestObjectStatsTrigger (8.44s)1069=== CONT TestLeadEndsOnShutdown10702026/11/09 12:16:02 INFO Received uploads request method=POST path=/api/pending_closures1071--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (8.46s)1072=== CONT TestService_AuthMiddleware_MTLSBoundSubjects10732026/11/09 12:16:02 INFO Received uploads request method=POST path=/api/pending_closures10742026/11/09 12:16:02 INFO Received uploads request method=POST path=/api/pending_closures10752026/11/09 12:16:02 INFO Received cleanup request method=DELETE path=/api/pending_closures10762026/11/09 12:16:03 INFO Aborted multipart uploads count=0 kept=010772026/11/09 12:16:03 WARN Force mode enabled - objects will be deleted immediately without grace period1078=== NAME TestOrphanedObjectsGC1079 orphaned_objects_gc_test.go:287: GC Test Summary:1080 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1081 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1082 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1083 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1084 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1085--- PASS: TestOrphanedObjectsGC (11.11s)1086=== CONT TestService_AuthMiddleware_MTLSProxyHeader10872026/11/09 12:16:03 INFO Received uploads request method=POST path=/api/pending_closures1088--- PASS: TestTombstonedObjectOfferedWithoutWaiting (8.38s)1089=== CONT TestService_AuthMiddleware10902026/11/09 12:16:03 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=010912026/11/09 12:16:03 INFO Vacuumed table table=pending_closures10922026/11/09 12:16:03 INFO Vacuumed table table=pending_objects10932026/11/09 12:16:03 INFO Vacuumed table table=multipart_uploads10942026/11/09 12:16:03 INFO Vacuumed table table=closures10952026/11/09 12:16:04 INFO Vacuumed table table=objects1096--- PASS: TestGCSweepDeliversEachKeyOnce (9.12s)1097=== CONT TestLeadIncumbentAnnouncesAtOnce1098=== NAME TestPinProtectsFromGC1099 client_integration_test.go:778: Pinned store path: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestPinProtectsFromGC2359245149/001/store/dmy8zbmp8svmx5pq7il9b518nfb6kgfg-pinned-file.txt1100 client_integration_test.go:779: Unpinned store path: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestPinProtectsFromGC2359245149/001/store/6sx7h9j9vcw8h17ywcfyc3crw875hlx9-unpinned-file.txt11012026/11/09 12:16:04 INFO Received uploads request method=POST path=/api/pending_closures11022026/11/09 12:16:04 INFO Received push request method=POST path=/api/pushes11032026/11/09 12:16:04 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11042026/11/09 12:16:04 INFO Uploading dmy8zbmp8svmx5pq7il9b518nfb6kgfg-pinned-file.txt (128B)11052026/11/09 12:16:04 INFO Aborted multipart uploads count=0 kept=011062026/11/09 12:16:04 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"11072026/11/09 12:16:04 WARN Force mode enabled - objects will be deleted immediately without grace period11082026/11/09 12:16:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11092026/11/09 12:16:04 WARN Failed to register uploaded object key=dmy8zbmp8svmx5pq7il9b518nfb6kgfg.ls error="server returned 404: 404 page not found\n"11102026/11/09 12:16:04 INFO Signed narinfos id=1 count=111112026/11/09 12:16:04 INFO Uploading 1 narinfos11122026/11/09 12:16:04 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=011132026/11/09 12:16:04 INFO Vacuumed table table=pending_closures11142026/11/09 12:16:04 INFO Received complete push request method=POST path=/api/pushes/1/complete11152026/11/09 12:16:04 WARN Failed to register uploaded object key=dmy8zbmp8svmx5pq7il9b518nfb6kgfg.narinfo error="server returned 404: 404 page not found\n"11162026/11/09 12:16:04 INFO Vacuumed table table=pending_objects11172026/11/09 12:16:04 INFO Vacuumed table table=multipart_uploads11182026/11/09 12:16:04 INFO Vacuumed table table=closures11192026/11/09 12:16:04 INFO Completed push id=1 objects=3 duration=29.93075ms11202026/11/09 12:16:04 INFO Upload complete. (384ms)11212026/11/09 12:16:04 INFO Received push request method=POST path=/api/pushes11222026/11/09 12:16:05 INFO Vacuumed table table=objects11232026/11/09 12:16:05 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)11242026/11/09 12:16:05 INFO Uploading 1aqamyjynrvkwz0gwja9g2yma9knf4c3-top (264B)11252026/11/09 12:16:05 INFO Uploading jx61qk9sh88hx04vjlwj4swi15l86fs4-shared-dep (136B)1126--- PASS: TestGCSweepSkipsPendingObjects (8.55s)1127=== CONT TestProxyWriteTimeout1128=== RUN TestProxyWriteTimeout/narinfo1129=== PAUSE TestProxyWriteTimeout/narinfo1130=== RUN TestProxyWriteTimeout/1_GiB_nar1131=== PAUSE TestProxyWriteTimeout/1_GiB_nar1132=== RUN TestProxyWriteTimeout/10_GiB_nar1133=== PAUSE TestProxyWriteTimeout/10_GiB_nar1134=== RUN TestProxyWriteTimeout/unknown_size1135=== PAUSE TestProxyWriteTimeout/unknown_size1136=== CONT TestLeadElectsOneAndHandsOver11372026/11/09 12:16:05 WARN Failed to register uploaded object key=jx61qk9sh88hx04vjlwj4swi15l86fs4.ls error="server returned 404: 404 page not found\n"11382026/11/09 12:16:05 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"11392026/11/09 12:16:05 WARN Failed to register uploaded object key=nar/1ygsx2rv4y4whpiqwrnj9cz76fjqnlmn1v3gm9hyfwja4dqi8i2f.nar.zst error="server returned 404: 404 page not found\n"11402026/11/09 12:16:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11412026/11/09 12:16:05 WARN Failed to register uploaded object key=1aqamyjynrvkwz0gwja9g2yma9knf4c3.ls error="server returned 404: 404 page not found\n"11422026/11/09 12:16:05 INFO Signed narinfos id=1 count=211432026/11/09 12:16:05 INFO Uploading 2 narinfos11442026/11/09 12:16:05 INFO Received push request method=POST path=/api/pushes11452026/11/09 12:16:05 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11462026/11/09 12:16:05 INFO Uploading 6sx7h9j9vcw8h17ywcfyc3crw875hlx9-unpinned-file.txt (128B)11472026/11/09 12:16:05 WARN Failed to register uploaded object key=jx61qk9sh88hx04vjlwj4swi15l86fs4.narinfo error="server returned 404: 404 page not found\n"11482026/11/09 12:16:05 INFO Received complete push request method=POST path=/api/pushes/1/complete11492026/11/09 12:16:05 WARN Failed to register uploaded object key=1aqamyjynrvkwz0gwja9g2yma9knf4c3.narinfo error="server returned 404: 404 page not found\n"11502026/11/09 12:16:05 WARN Failed to register uploaded object key=6sx7h9j9vcw8h17ywcfyc3crw875hlx9.ls error="server returned 404: 404 page not found\n"11512026/11/09 12:16:05 INFO Completed push id=1 objects=6 duration=65.294417ms11522026/11/09 12:16:05 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11532026/11/09 12:16:05 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"11542026/11/09 12:16:05 INFO Upload complete. (455ms)11552026/11/09 12:16:05 INFO Signed narinfos id=2 count=11156=== NAME TestClientSharedPathCommittedMidPush1157 client_integration_test.go:727: Retrieved narinfo from S3:1158 StorePath: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientSharedPathCommittedMidPush782393417/001/store/jx61qk9sh88hx04vjlwj4swi15l86fs4-shared-dep1159 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1160 Compression: zstd1161 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821162 NarSize: 1361163 References: 1164 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n11652026/11/09 12:16:05 INFO Uploading 1 narinfos1166 client_integration_test.go:727: Retrieved narinfo from S3:1167 StorePath: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientSharedPathCommittedMidPush782393417/001/store/1aqamyjynrvkwz0gwja9g2yma9knf4c3-top1168 URL: nar/1ygsx2rv4y4whpiqwrnj9cz76fjqnlmn1v3gm9hyfwja4dqi8i2f.nar.zst1169 Compression: zstd1170 NarHash: sha256:1ygsx2rv4y4whpiqwrnj9cz76fjqnlmn1v3gm9hyfwja4dqi8i2f1171 NarSize: 2641172 References: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientSharedPathCommittedMidPush782393417/001/store/jx61qk9sh88hx04vjlwj4swi15l86fs4-shared-dep1173 CA: text:sha256:0f2kpsys8ad39df2b64nslw8350m7j7p5lp131pq48g29lrw9yi911742026/11/09 12:16:05 INFO Received complete push request method=POST path=/api/pushes/2/complete11752026/11/09 12:16:05 WARN Failed to register uploaded object key=6sx7h9j9vcw8h17ywcfyc3crw875hlx9.narinfo error="server returned 404: 404 page not found\n"1176--- PASS: TestClientSharedPathCommittedMidPush (9.34s)11772026/11/09 12:16:05 INFO Completed push id=2 objects=3 duration=1.662833ms1178=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT11792026/11/09 12:16:05 INFO Upload complete. (328ms)11802026/11/09 12:16:05 INFO Starting cleanup of old closures method=DELETE path=/api/closures11812026/11/09 12:16:05 INFO Garbage collection started11822026/11/09 12:16:05 INFO Aborted multipart uploads count=0 kept=011832026/11/09 12:16:05 WARN Force mode enabled - objects will be deleted immediately without grace period1184=== NAME TestClientWithDependencies1185 client_integration_test.go:660: Built derivation: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientWithDependencies2244202937/001/store/qvh1qd9s9b3jdkhbalqpanfs5ij8k4b0-test-script1186=== NAME TestClientMultipleUploads1187 client_integration_test.go:405: Created store path 0: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientMultipleUploads2667145021/001/store/flca01xs00xhk0kha8gvrb1xmn5jbj89-test-file-0.txt1188=== NAME TestClientWithDependencies1189 client_integration_test.go:662: Found 1 dependencies (including self)11902026/11/09 12:16:06 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=01191=== NAME TestClientMultipleUploads1192 client_integration_test.go:405: Created store path 1: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientMultipleUploads2667145021/001/store/lwb94i2c3ia09kqb87m09r3s4lhhgcrb-test-file-1.txt11932026/11/09 12:16:06 INFO Received push request method=POST path=/api/pushes11942026/11/09 12:16:06 INFO Received uploads request method=POST path=/api/pending_closures11952026/11/09 12:16:06 INFO Vacuumed table table=pending_closures11962026/11/09 12:16:06 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11972026/11/09 12:16:06 INFO Uploading qvh1qd9s9b3jdkhbalqpanfs5ij8k4b0-test-script (136B)11982026/11/09 12:16:06 INFO Vacuumed table table=pending_objects11992026/11/09 12:16:06 INFO Vacuumed table table=multipart_uploads12002026/11/09 12:16:06 WARN Failed to register uploaded object key=qvh1qd9s9b3jdkhbalqpanfs5ij8k4b0.ls error="server returned 404: 404 page not found\n"12012026/11/09 12:16:06 INFO Vacuumed table table=closures12022026/11/09 12:16:06 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"12032026/11/09 12:16:06 WARN Failed to register uploaded object key=log/8zhg5p6rb1vfn9gf2c4b6l5lav6fr1hh-test-script.drv error="server returned 404: 404 page not found\n"12042026/11/09 12:16:06 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12052026/11/09 12:16:06 INFO Signed narinfos id=1 count=112062026/11/09 12:16:06 INFO Uploading 1 narinfos12072026/11/09 12:16:06 INFO Vacuumed table table=objects1208 client_integration_test.go:405: Created store path 2: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientMultipleUploads2667145021/001/store/h68w8m8g51pr4r5j2ag8r7p9qilfzymi-test-file-2.txt12092026/11/09 12:16:06 INFO Received complete push request method=POST path=/api/pushes/1/complete12102026/11/09 12:16:06 WARN Failed to register uploaded object key=qvh1qd9s9b3jdkhbalqpanfs5ij8k4b0.narinfo error="server returned 404: 404 page not found\n"12112026/11/09 12:16:06 INFO Aborted multipart uploads count=0 kept=012122026/11/09 12:16:06 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=012132026/11/09 12:16:06 INFO Completed push id=1 objects=4 duration=27.647542ms12142026/11/09 12:16:06 INFO Upload complete. (398ms)1215=== NAME TestClientWithDependencies1216 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientWithDependencies2244202937/001/store) requires matching store prefix12172026/11/09 12:16:06 INFO Vacuumed table table=pending_closures1218--- PASS: TestClientWithDependencies (9.56s)1219=== CONT TestCompleteMultipartUnregistered12202026/11/09 12:16:06 INFO Vacuumed table table=pending_objects12212026/11/09 12:16:06 INFO Aborted multipart uploads count=0 kept=012222026/11/09 12:16:06 INFO Vacuumed table table=multipart_uploads12232026/11/09 12:16:06 WARN Force mode enabled - objects will be deleted immediately without grace period12242026/11/09 12:16:06 INFO Vacuumed table table=closures12252026/11/09 12:16:06 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=012262026/11/09 12:16:06 INFO Vacuumed table table=pending_closures12272026/11/09 12:16:06 INFO Vacuumed table table=pending_objects12282026/11/09 12:16:06 INFO Vacuumed table table=multipart_uploads12292026/11/09 12:16:06 INFO Vacuumed table table=objects12302026/11/09 12:16:06 INFO Vacuumed table table=closures12312026/11/09 12:16:06 INFO Vacuumed table table=objects1232--- PASS: TestGCMetrics (8.53s)1233=== CONT TestConnectWaitsForAPeerMigration12342026/11/09 12:16:06 INFO Received push request method=POST path=/api/pushes12352026/11/09 12:16:06 INFO Aborted multipart uploads count=0 kept=012362026/11/09 12:16:06 WARN Force mode enabled - objects will be deleted immediately without grace period12372026/11/09 12:16:06 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=012382026/11/09 12:16:06 INFO Vacuumed table table=pending_closures12392026/11/09 12:16:06 INFO Vacuumed table table=pending_objects12402026/11/09 12:16:06 INFO Vacuumed table table=multipart_uploads12412026/11/09 12:16:06 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)12422026/11/09 12:16:06 INFO Uploading flca01xs00xhk0kha8gvrb1xmn5jbj89-test-file-0.txt (160B)12432026/11/09 12:16:06 INFO Uploading lwb94i2c3ia09kqb87m09r3s4lhhgcrb-test-file-1.txt (160B)12442026/11/09 12:16:06 INFO Uploading h68w8m8g51pr4r5j2ag8r7p9qilfzymi-test-file-2.txt (160B)12452026/11/09 12:16:06 INFO Vacuumed table table=closures12462026/11/09 12:16:06 INFO Vacuumed table table=objects1247--- PASS: TestPushDedupSurvivesConcurrentGC (8.68s)1248=== CONT TestService_verifyS3ReuploadsStaleNarinfo1249=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1250=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1251=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1252=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1253=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1254=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1255=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1256=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1257=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1258=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1259=== CONT TestService_verifyS3Integrity12602026/11/09 12:16:06 WARN Failed to register uploaded object key=flca01xs00xhk0kha8gvrb1xmn5jbj89.ls error="server returned 404: 404 page not found\n"12612026/11/09 12:16:06 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"12622026/11/09 12:16:06 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"12632026/11/09 12:16:06 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"12642026/11/09 12:16:06 WARN Failed to register uploaded object key=h68w8m8g51pr4r5j2ag8r7p9qilfzymi.ls error="server returned 404: 404 page not found\n"12652026/11/09 12:16:06 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12662026/11/09 12:16:06 WARN Failed to register uploaded object key=lwb94i2c3ia09kqb87m09r3s4lhhgcrb.ls error="server returned 404: 404 page not found\n"12672026/11/09 12:16:06 INFO Signed narinfos id=1 count=312682026/11/09 12:16:06 INFO Uploading 3 narinfos12692026/11/09 12:16:06 WARN Failed to register uploaded object key=lwb94i2c3ia09kqb87m09r3s4lhhgcrb.narinfo error="server returned 404: 404 page not found\n"12702026/11/09 12:16:06 WARN Failed to register uploaded object key=h68w8m8g51pr4r5j2ag8r7p9qilfzymi.narinfo error="server returned 404: 404 page not found\n"12712026/11/09 12:16:06 INFO Received complete push request method=POST path=/api/pushes/1/complete12722026/11/09 12:16:06 WARN Failed to register uploaded object key=flca01xs00xhk0kha8gvrb1xmn5jbj89.narinfo error="server returned 404: 404 page not found\n"12732026/11/09 12:16:06 INFO Completed push id=1 objects=9 duration=34.686709ms12742026/11/09 12:16:06 INFO Upload complete. (360ms)1275=== NAME TestClientMultipleUploads1276 client_integration_test.go:416: Uploaded 3 paths in 430.935584ms12772026/11/09 12:16:06 INFO Received uploads request method=POST path=/api/pending_closures1278--- PASS: TestDeduplicatedObjectsRecordedAsPending (9.02s)1279=== CONT TestResolveDBConnectionString1280=== RUN TestResolveDBConnectionString/flag_wins1281=== PAUSE TestResolveDBConnectionString/flag_wins1282=== RUN TestResolveDBConnectionString/file_when_flag_empty1283=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1284=== RUN TestResolveDBConnectionString/missing_file_is_an_error1285=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1286=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1287=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1288=== RUN TestResolveDBConnectionString/nothing_configured1289=== PAUSE TestResolveDBConnectionString/nothing_configured1290=== CONT TestService_createPendingClosureHandler1291--- PASS: TestClientMultipleUploads (9.38s)1292=== CONT TestService_cleanupPendingClosuresHandler1293=== NAME TestClientIntegration1294 client_integration_test.go:291: Created store path: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientIntegration4126525431/002/store/yvv2qlx279qkgr0vjk0v832qng19w42z-test-file.txt12952026/11/09 12:16:07 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=012962026/11/09 12:16:07 INFO Received create pin request method=POST path=/api/pins/myapp12972026/11/09 12:16:07 INFO Created/updated pin name=myapp store_path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestPinProtectsFromGC2359245149/001/store/dmy8zbmp8svmx5pq7il9b518nfb6kgfg-pinned-file.txt narinfo_key=dmy8zbmp8svmx5pq7il9b518nfb6kgfg.narinfo12982026/11/09 12:16:07 INFO Starting cleanup of old closures method=DELETE path=/api/closures12992026/11/09 12:16:07 INFO Garbage collection started13002026/11/09 12:16:07 INFO Aborted multipart uploads count=0 kept=013012026/11/09 12:16:07 INFO Received push request method=POST path=/api/pushes13022026/11/09 12:16:07 WARN Force mode enabled - objects will be deleted immediately without grace period13032026/11/09 12:16:07 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=013042026/11/09 12:16:07 INFO Vacuumed table table=pending_closures13052026/11/09 12:16:07 INFO Vacuumed table table=pending_objects13062026/11/09 12:16:07 INFO Vacuumed table table=multipart_uploads13072026/11/09 12:16:07 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13082026/11/09 12:16:07 INFO Uploading yvv2qlx279qkgr0vjk0v832qng19w42z-test-file.txt (152B)13092026/11/09 12:16:07 INFO Vacuumed table table=closures13102026/11/09 12:16:07 INFO Vacuumed table table=objects13112026/11/09 12:16:07 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"13122026/11/09 12:16:07 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1313--- PASS: TestGCBugBareHashReferences (8.77s)13142026/11/09 12:16:07 WARN Failed to register uploaded object key=yvv2qlx279qkgr0vjk0v832qng19w42z.ls error="server returned 404: 404 page not found\n"13152026/11/09 12:16:07 INFO Signed narinfos id=1 count=11316=== CONT TestUploadHandlersRejectOversizedBody13172026/11/09 12:16:07 INFO Uploading 1 narinfos13182026/11/09 12:16:07 INFO Received complete push request method=POST path=/api/pushes/1/complete13192026/11/09 12:16:07 WARN Failed to register uploaded object key=yvv2qlx279qkgr0vjk0v832qng19w42z.narinfo error="server returned 404: 404 page not found\n"13202026/11/09 12:16:07 INFO Completed push id=1 objects=3 duration=42.228125ms13212026/11/09 12:16:07 INFO Upload complete. (309ms)1322=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1323=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1324=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1325=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1326=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1327=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1328=== CONT TestUploadHandlersRejectInvalidKeys1329=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1330=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1331=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1332=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1333=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1334=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1335=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1336=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1337=== CONT TestIsValidUploadKey1338=== RUN TestIsValidUploadKey/narinfo1339=== PAUSE TestIsValidUploadKey/narinfo1340=== RUN TestIsValidUploadKey/nar_zst1341=== PAUSE TestIsValidUploadKey/nar_zst1342=== RUN TestIsValidUploadKey/nar_xz1343=== PAUSE TestIsValidUploadKey/nar_xz1344=== RUN TestIsValidUploadKey/nar_plain1345=== PAUSE TestIsValidUploadKey/nar_plain1346=== RUN TestIsValidUploadKey/listing1347=== PAUSE TestIsValidUploadKey/listing1348=== RUN TestIsValidUploadKey/build_log1349=== PAUSE TestIsValidUploadKey/build_log1350=== RUN TestIsValidUploadKey/build_log_home-manager_file1351=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1352=== RUN TestIsValidUploadKey/build_log_plus_in_name1353=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1354=== RUN TestIsValidUploadKey/build_log_question_mark1355=== PAUSE TestIsValidUploadKey/build_log_question_mark1356=== RUN TestIsValidUploadKey/build_log_equals1357=== PAUSE TestIsValidUploadKey/build_log_equals1358=== RUN TestIsValidUploadKey/realisation1359=== PAUSE TestIsValidUploadKey/realisation1360=== RUN TestIsValidUploadKey/realisation_plus_in_output1361=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1362=== RUN TestIsValidUploadKey/nix-cache-info1363=== PAUSE TestIsValidUploadKey/nix-cache-info1364=== RUN TestIsValidUploadKey/index.html1365=== PAUSE TestIsValidUploadKey/index.html1366=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1367=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1368=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1369=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1370=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1371=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1372=== RUN TestIsValidUploadKey/traversal1373=== PAUSE TestIsValidUploadKey/traversal1374=== RUN TestIsValidUploadKey/traversal_nar1375=== PAUSE TestIsValidUploadKey/traversal_nar1376=== RUN TestIsValidUploadKey/absolute1377=== PAUSE TestIsValidUploadKey/absolute1378=== RUN TestIsValidUploadKey/empty_key1379=== PAUSE TestIsValidUploadKey/empty_key1380=== RUN TestIsValidUploadKey/unknown_type1381=== PAUSE TestIsValidUploadKey/unknown_type1382=== CONT TestPendingClosureWriteTimeout1383=== RUN TestPendingClosureWriteTimeout/empty1384=== PAUSE TestPendingClosureWriteTimeout/empty1385=== RUN TestPendingClosureWriteTimeout/400_objects1386=== PAUSE TestPendingClosureWriteTimeout/400_objects1387=== RUN TestPendingClosureWriteTimeout/670k_objects1388=== PAUSE TestPendingClosureWriteTimeout/670k_objects1389=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1390=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1391=== CONT TestGenerateLandingPage1392--- PASS: TestGenerateLandingPage (0.00s)1393=== CONT TestMetricsCommit13942026/11/09 12:16:07 INFO All 1 paths already cached1395=== NAME TestClientIntegration1396 client_integration_test.go:317: Retrieved narinfo from S3:1397 StorePath: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientIntegration4126525431/002/store/yvv2qlx279qkgr0vjk0v832qng19w42z-test-file.txt1398 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1399 Compression: zstd1400 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11401 NarSize: 1521402 References: 1403 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11404 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1405 client_integration_test.go:318: Decompressed .ls content (64 bytes):1406 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1407--- PASS: TestCacheStatsHandler (8.82s)1408=== CONT TestMetricsInventory1409=== NAME TestClientCADerivations1410 client_ca_test.go:136: Built CA derivation: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientCADerivations1250176364/001/store/n4camw53d9sag2c0ffcxp34iz5cv60qh-ca-test1411 client_ca_test.go:139: Found 1 dependencies (including self)14122026/11/09 12:16:08 INFO Received push request method=POST path=/api/pushes14132026/11/09 12:16:08 INFO Object in database but missing from S3 key=yvv2qlx279qkgr0vjk0v832qng19w42z.ls14142026/11/09 12:16:08 WARN Found objects in DB but missing from S3, will re-upload count=114152026/11/09 12:16:08 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14162026/11/09 12:16:08 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld1 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1417--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (8.92s)1418=== CONT TestNARDeduplicationMetadataUploadBug14192026/11/09 12:16:08 INFO Received complete push request method=POST path=/api/pushes/2/complete14202026/11/09 12:16:08 WARN Failed to register uploaded object key=yvv2qlx279qkgr0vjk0v832qng19w42z.ls error="server returned 404: 404 page not found\n"14212026/11/09 12:16:08 INFO Completed push id=2 objects=3 duration=4.082959ms14222026/11/09 12:16:08 INFO Upload complete. (205ms)1423=== NAME TestClientIntegration1424 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1425 client_integration_test.go:335: Decompressed .ls content (49 bytes):1426 {"version":1,"root":{"type":"regular","size":39}}14272026/11/09 12:16:08 INFO Received push request method=POST path=/api/pushes14282026/11/09 12:16:08 INFO Aborted multipart uploads count=1 kept=014292026/11/09 12:16:08 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14302026/11/09 12:16:08 INFO Uploading n4camw53d9sag2c0ffcxp34iz5cv60qh-ca-test (144B)14312026/11/09 12:16:08 INFO Received cleanup request method=DELETE path=/api/pending_closures14322026/11/09 12:16:08 WARN Failed to register uploaded object key=n4camw53d9sag2c0ffcxp34iz5cv60qh.ls error="server returned 404: 404 page not found\n"14332026/11/09 12:16:08 INFO Aborted multipart uploads count=1 kept=01434--- PASS: TestPendingCleanupUsesOneCutoff (14.08s)1435=== CONT TestCreatePendingClosureRejectsOversizedNAR14362026/11/09 12:16:08 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"14372026/11/09 12:16:08 INFO Received uploads request method=POST path=/api/pending_closures1438--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.01s)1439=== CONT TestCacheConfigHandlerMaxNarSize1440--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1441=== CONT TestEnsureAbortUploadsRule1442--- PASS: TestService_ReadScope_PublicByDefault (8.44s)1443=== CONT TestCompletedNarNotReofferedAcrossClosures14442026/11/09 12:16:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14452026/11/09 12:16:08 WARN Failed to register uploaded object key=log/45dimz2b3bassm520c6c0rpkmdrsly9d-ca-test.drv error="server returned 404: 404 page not found\n"14462026/11/09 12:16:08 INFO Signed narinfos id=1 count=114472026/11/09 12:16:08 INFO Uploading 1 narinfos14482026/11/09 12:16:08 INFO Received push request method=POST path=/api/pushes14492026/11/09 12:16:08 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)14502026/11/09 12:16:09 INFO Received complete push request method=POST path=/api/pushes/1/complete14512026/11/09 12:16:09 WARN Failed to register uploaded object key=n4camw53d9sag2c0ffcxp34iz5cv60qh.narinfo error="server returned 404: 404 page not found\n"14522026/11/09 12:16:09 INFO Received complete push request method=POST path=/api/pushes/3/complete14532026/11/09 12:16:09 WARN Failed to register uploaded object key=yvv2qlx279qkgr0vjk0v832qng19w42z.ls error="server returned 404: 404 page not found\n"14542026/11/09 12:16:09 INFO Completed push id=3 objects=3 duration=1.058875ms14552026/11/09 12:16:09 INFO Upload complete. (210ms)14562026/11/09 12:16:09 INFO Completed push id=1 objects=4 duration=50.515167ms14572026/11/09 12:16:09 INFO Upload complete. (554ms)1458=== NAME TestClientIntegration1459 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1460=== NAME TestClientCADerivations1461 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientCADerivations1250176364/001/store/n4camw53d9sag2c0ffcxp34iz5cv60qh-ca-test1462 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1463 Compression: zstd1464 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1465 NarSize: 1441466 References: 1467 Deriver: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientCADerivations1250176364/001/store/45dimz2b3bassm520c6c0rpkmdrsly9d-ca-test.drv1468 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1469=== NAME TestClientIntegration1470 client_integration_test.go:352: Decompressed .ls content (49 bytes):1471 {"version":1,"root":{"type":"regular","size":39}}1472=== NAME TestClientCADerivations1473 client_ca_test.go:185: Checking for realisation files in S3...1474=== NAME TestClientIntegration1475 client_integration_test.go:363: Testing garbage collection...1476=== NAME TestClientCADerivations1477 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1478 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache14792026/11/09 12:16:09 INFO Starting cleanup of old closures method=DELETE path=/api/closures14802026/11/09 12:16:09 INFO Garbage collection started14812026/11/09 12:16:09 INFO Aborted multipart uploads count=0 kept=014822026/11/09 12:16:09 WARN Force mode enabled - objects will be deleted immediately without grace period1483=== RUN TestService_RequireScope_OIDC/builder_may_write1484=== PAUSE TestService_RequireScope_OIDC/builder_may_write1485=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1486=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1487=== RUN TestService_RequireScope_OIDC/ops_may_admin1488=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1489=== RUN TestService_RequireScope_OIDC/ops_may_not_write1490=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1491=== RUN TestService_RequireScope_OIDC/reader_may_not_write1492=== NAME TestClientCADerivations1493 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket55?endpoint=http://localhost:51514®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientCADerivations1250176364/001/store'1494 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11495=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1496=== RUN TestService_RequireScope_OIDC/static_token_may_admin1497=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1498=== RUN TestService_RequireScope_OIDC/static_token_may_write1499=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1500=== RUN TestService_RequireScope_OIDC/reader_may_read1501=== PAUSE TestService_RequireScope_OIDC/reader_may_read1502=== RUN TestService_RequireScope_OIDC/writer_implies_read1503=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1504=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1505=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1506=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1507=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1508=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1509=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1510=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1511=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1512=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1513=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1514=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1515--- PASS: TestClientCADerivations (10.52s)1516=== CONT TestSkippedUploadsHandler15172026/11/09 12:16:09 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001518--- PASS: TestSkippedUploadsHandler (0.01s)1519=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1520=== NAME TestPinProtectsFromGC1521 client_integration_test.go:887: Pin successfully protected closure from garbage collection1522--- PASS: TestPinProtectsFromGC (14.08s)1523=== CONT TestParseSize1524--- PASS: TestParseSize (0.00s)1525=== CONT TestDeleteClosuresRacingPins1526=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token15272026/11/09 12:16:09 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=01528=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1529=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1530=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1531=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1532=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1533=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1534=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1535=== CONT TestService_Rustfstest15362026/11/09 12:16:09 INFO Vacuumed table table=pending_closures15372026/11/09 12:16:09 INFO Vacuumed table table=pending_objects15382026/11/09 12:16:09 INFO Vacuumed table table=multipart_uploads15392026/11/09 12:16:10 INFO Vacuumed table table=closures15402026/11/09 12:16:10 INFO Vacuumed table table=objects1541--- PASS: TestService_ReadAuthMiddleware (8.43s)1542=== CONT TestClientFallsBackToClosures15432026/11/09 12:16:10 INFO lead: acquired remote=192.0.2.1:123415442026/11/09 12:16:11 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"15452026/11/09 12:16:11 WARN mTLS auth: bound subjects configured but subject DN unavailable15462026/11/09 12:16:11 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1547--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (8.49s)1548=== CONT TestPresignedUploadRegisteredBeforeCommit15492026/11/09 12:16:11 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01550=== NAME TestClientIntegration1551 client_integration_test.go:370: Objects in database after GC:1552 client_integration_test.go:370: Successfully deleted all objects with GC --force1553--- PASS: TestClientIntegration (12.55s)1554=== CONT TestClientPushesUseOnePush1555--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (7.72s)1556=== CONT TestService_readinessHandler15572026/11/09 12:16:11 INFO lead: released remote=192.0.2.1:12341558--- PASS: TestLeadEndsOnShutdown (9.80s)1559=== CONT TestGracefulShutdownDrainsInflight15602026/11/09 12:16:11 INFO Starting HTTP server address=127.0.0.1:5182215612026/11/09 12:16:11 INFO Shutdown signal received, draining in-flight requests timeout=10s1562--- PASS: TestGracefulShutdownDrainsInflight (0.05s)1563=== CONT TestPush_SignsNarinfosOfItsPendingObjects15642026/11/09 12:16:11 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1565--- PASS: TestService_AuthMiddleware (8.05s)1566=== CONT TestService_healthCheckHandler15672026/11/09 12:16:12 INFO lead: acquired remote=192.0.2.1:123415682026/11/09 12:16:12 INFO lead: released remote=192.0.2.1:12341569--- PASS: TestLeadIncumbentAnnouncesAtOnce (8.21s)1570=== CONT TestCompleteMultipartUpload_ErrorButObjectExists15712026/11/09 12:16:12 INFO lead: acquired remote=192.0.2.1:123415722026/11/09 12:16:13 INFO Received uploads request method=POST path=/api/pending_closures1573--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (8.05s)1574=== CONT TestSharedNarBothUploadsComplete15752026/11/09 12:16:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15762026/11/09 12:16:13 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1577--- PASS: TestCompleteMultipartUnregistered (7.38s)1578=== CONT TestGCTaskStore_PhaseUpdates1579--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1580=== CONT TestGCTaskStore_CompletedAllowsNewTask1581--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1582=== CONT TestGCTaskStore_Fail1583--- PASS: TestGCTaskStore_Fail (0.00s)1584=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1585--- PASS: TestConnectWaitsForAPeerMigration (7.53s)1586=== CONT TestPush_RejectsBadRequests15872026/11/09 12:16:14 INFO lead: released remote=192.0.2.1:123415882026/11/09 12:16:14 INFO lead: acquired remote=192.0.2.1:123415892026/11/09 12:16:14 INFO Received cleanup request method=DELETE path=/api/pending_closures15902026/11/09 12:16:14 INFO Aborted multipart uploads count=0 kept=015912026/11/09 12:16:14 INFO Received uploads request method=POST path=/api/pending_closures15922026/11/09 12:16:14 INFO Received cleanup request method=DELETE path=/api/pending_closures15932026/11/09 12:16:14 INFO Aborted multipart uploads count=1 kept=015942026/11/09 12:16:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15952026-11-09 12:16:14.545 UTC [62787] ERROR: Closure does not exist: id=115962026-11-09 12:16:14.545 UTC [62787] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE15972026-11-09 12:16:14.545 UTC [62787] STATEMENT: -- name: CommitPendingClosure :one1598 SELECT commit_pending_closure($1::bigint)::bigint1599 1600--- PASS: TestService_cleanupPendingClosuresHandler (7.69s)1601=== CONT TestServerTLSConfig/no_client_CA1602=== CONT TestServerTLSConfig/not_a_PEM_file1603=== CONT TestServerTLSConfig/missing_CA_file1604=== CONT TestGCEndsOnShutdown/before_the_run1605--- PASS: TestServerTLSConfig (0.00s)1606 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1607 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.05s)1608 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)16092026/11/09 12:16:14 INFO Received uploads request method=POST path=/api/pending_closures16102026/11/09 12:16:15 INFO lead: released remote=192.0.2.1:12341611--- PASS: TestLeadElectsOneAndHandsOver (10.12s)1612=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark16132026/11/09 12:16:15 INFO Received uploads request method=POST path=/api/pending_closures16142026/11/09 12:16:15 INFO Received uploads request method=POST path=/api/pending_closures16152026/11/09 12:16:15 INFO Received uploads request method=POST path=/api/pending_closures16162026/11/09 12:16:15 INFO Received push request method=POST path=/api/pushes16172026/11/09 12:16:16 INFO Received complete push request method=POST path=/api/pushes/1/complete16182026/11/09 12:16:16 INFO Completed push id=1 objects=4 duration=79.133042ms16192026/11/09 12:16:16 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16202026/11/09 12:16:16 INFO Completed upload id=2 objects=2 duration=1.306333ms1621--- PASS: TestMetricsCommit (8.44s)1622=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1623--- PASS: TestMetricsInventory (8.60s)1624=== CONT TestIsValidCachePath/narinfo1625=== CONT TestIsValidCachePath/index.html1626=== CONT TestIsValidCachePath/short_hash1627=== CONT TestIsValidCachePath/wrong_extension1628=== CONT TestIsValidCachePath/leading_slash1629=== CONT TestIsValidCachePath/empty1630=== CONT TestIsValidCachePath/random_path1631=== CONT TestIsValidCachePath/invalid_char_u1632=== CONT TestIsValidCachePath/invalid_char_e1633=== CONT TestIsValidCachePath/traversal_in_middle1634=== CONT TestIsValidCachePath/traversal_parent1635=== CONT TestIsValidCachePath/nar_uncompressed1636=== CONT TestIsValidCachePath/nix-cache-info1637=== CONT TestIsValidCachePath/realisation1638=== CONT TestIsValidCachePath/log1639=== CONT TestIsValidCachePath/ls1640=== CONT TestIsValidCachePath/nar_xz1641=== CONT TestIsValidCachePath/nar_bz21642=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1643=== CONT TestIsValidCachePath/nar_zst1644--- PASS: TestIsValidCachePath (0.00s)1645 --- PASS: TestIsValidCachePath/narinfo (0.00s)1646 --- PASS: TestIsValidCachePath/index.html (0.00s)1647 --- PASS: TestIsValidCachePath/short_hash (0.00s)1648 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1649 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1650 --- PASS: TestIsValidCachePath/empty (0.00s)1651 --- PASS: TestIsValidCachePath/random_path (0.00s)1652 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1653 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1654 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1655 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1656 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1657 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1658 --- PASS: TestIsValidCachePath/realisation (0.00s)1659 --- PASS: TestIsValidCachePath/log (0.00s)1660 --- PASS: TestIsValidCachePath/ls (0.00s)1661 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1662 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1663 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1664 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1665=== CONT TestParseSingleRange/none1666=== CONT TestParseSingleRange/open-ended1667=== CONT TestParseSingleRange/start_far_past_EOF1668=== CONT TestParseSingleRange/start_past_EOF1669=== CONT TestParseSingleRange/single_byte1670=== CONT TestParseSingleRange/suffix_exceeds_size1671=== CONT TestParseSingleRange/suffix1672=== CONT TestParseSingleRange/end_clamped_to_size1673=== CONT TestParseSingleRange/malformed_both_empty1674=== CONT TestParseSingleRange/closed1675=== CONT TestParseSingleRange/malformed_end_before_start1676=== CONT TestParseSingleRange/multi-range_ignored1677=== CONT TestParseSingleRange/malformed_no_dash1678=== CONT TestParseSingleRange/unknown_unit1679--- PASS: TestParseSingleRange (0.00s)1680 --- PASS: TestParseSingleRange/none (0.00s)1681 --- PASS: TestParseSingleRange/open-ended (0.00s)1682 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1683 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1684 --- PASS: TestParseSingleRange/single_byte (0.00s)1685 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1686 --- PASS: TestParseSingleRange/suffix (0.00s)1687 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1688 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1689 --- PASS: TestParseSingleRange/closed (0.00s)1690 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1691 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1692 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1693 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1694=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1695=== NAME TestOrphanedObjectsGCStressTest1696 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1697 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion16982026/11/09 12:16:17 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16992026/11/09 12:16:17 INFO Received uploads request method=POST path=/api/pending_closures17002026/11/09 12:16:17 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLjBlOTE0NjEzLWM5OTItNDNmZS04ODg3LThlYmQ5ZGQzYzIxM3gxNzk0MjI2NTc0OTMzNDU0MDAw parts=1017012026/11/09 12:16:17 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17022026/11/09 12:16:17 INFO Completed upload id=1 objects=2 duration=47.837084ms17032026/11/09 12:16:17 INFO Received uploads request method=POST path=/api/pending_closures17042026/11/09 12:16:17 INFO Received uploads request method=POST path=/api/pending_closures17052026/11/09 12:16:17 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo17062026/11/09 12:16:17 WARN Found objects in DB but missing from S3, will re-upload count=11707--- PASS: TestService_verifyS3Integrity (11.30s)1708=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1709=== NAME TestNARDeduplicationMetadataUploadBug1710 metadata_upload_test.go:48: First store path: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestNARDeduplicationMetadataUploadBug2253590372/001/store/c0bpi7p8l3j641qm7dx1snrznxapwpd3-file1.txt17112026/11/09 12:16:18 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17122026/11/09 12:16:18 INFO Received push request method=POST path=/api/pushes17132026/11/09 12:16:18 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17142026/11/09 12:16:18 INFO Uploading c0bpi7p8l3j641qm7dx1snrznxapwpd3-file1.txt (160B)17152026/11/09 12:16:18 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLmM5YWU0NTJiLWRhNGMtNDcwMy1hZmNlLWI1MTFlNzg0MmJjM3gxNzk0MjI2NTc1NTEwMzQwMDAw parts=1017162026/11/09 12:16:18 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete17172026/11/09 12:16:18 INFO Completed upload id=1 objects=2 duration=42.33275ms17182026/11/09 12:16:18 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000017192026/11/09 12:16:18 WARN Failed to register uploaded object key=c0bpi7p8l3j641qm7dx1snrznxapwpd3.ls error="server returned 404: 404 page not found\n"17202026/11/09 12:16:18 INFO Received uploads request method=POST path=/api/pending_closures17212026/11/09 12:16:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17222026/11/09 12:16:18 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"17232026/11/09 12:16:18 INFO Starting cleanup of old closures method=DELETE path=/api/closures17242026/11/09 12:16:18 INFO Signed narinfos id=1 count=117252026/11/09 12:16:18 INFO Uploading 1 narinfos17262026/11/09 12:16:18 INFO Aborted multipart uploads count=0 kept=017272026/11/09 12:16:18 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=017282026/11/09 12:16:18 INFO Received complete push request method=POST path=/api/pushes/1/complete17292026/11/09 12:16:18 WARN Failed to register uploaded object key=c0bpi7p8l3j641qm7dx1snrznxapwpd3.narinfo error="server returned 404: 404 page not found\n"17302026/11/09 12:16:18 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket77 days=21731--- PASS: TestEnsureAbortUploadsRule (9.64s)1732=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows17332026/11/09 12:16:18 INFO Vacuumed table table=pending_closures17342026/11/09 12:16:18 INFO Completed push id=1 objects=3 duration=88.925125ms17352026/11/09 12:16:18 INFO Upload complete. (534ms)1736=== NAME TestNARDeduplicationMetadataUploadBug1737 metadata_upload_test.go:54: Retrieved narinfo from S3:1738 StorePath: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestNARDeduplicationMetadataUploadBug2253590372/001/store/c0bpi7p8l3j641qm7dx1snrznxapwpd3-file1.txt17392026/11/09 12:16:18 INFO Vacuumed table table=pending_objects1740 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1741 Compression: zstd1742 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1743 NarSize: 1601744 References: 1745 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1746 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1747 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1748 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}17492026/11/09 12:16:18 INFO Vacuumed table table=multipart_uploads17502026/11/09 12:16:18 INFO Vacuumed table table=closures17512026/11/09 12:16:18 INFO Vacuumed table table=objects17522026/11/09 12:16:18 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001753--- PASS: TestService_createPendingClosureHandler (11.85s)1754=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check17552026/11/09 12:16:18 INFO Received uploads request method=POST path=/api/pending_closures1756=== NAME TestNARDeduplicationMetadataUploadBug1757 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestNARDeduplicationMetadataUploadBug2253590372/001/store/srangfdhbcd7ygiip3phxx6cscbrpip3-file2.txt17582026/11/09 12:16:18 INFO Received push request method=POST path=/api/pushes17592026/11/09 12:16:18 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)17602026/11/09 12:16:19 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17612026/11/09 12:16:19 WARN Failed to register uploaded object key=srangfdhbcd7ygiip3phxx6cscbrpip3.ls error="server returned 404: 404 page not found\n"17622026/11/09 12:16:19 INFO Signed narinfos id=2 count=117632026/11/09 12:16:19 INFO Uploading 1 narinfos17642026/11/09 12:16:19 INFO Received complete push request method=POST path=/api/pushes/2/complete17652026/11/09 12:16:19 WARN Failed to register uploaded object key=srangfdhbcd7ygiip3phxx6cscbrpip3.narinfo error="server returned 404: 404 page not found\n"17662026/11/09 12:16:19 INFO Completed push id=2 objects=3 duration=2.457417ms17672026/11/09 12:16:19 INFO Upload complete. (307ms)1768 metadata_upload_test.go:76: Retrieved narinfo from S3:1769 StorePath: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestNARDeduplicationMetadataUploadBug2253590372/001/store/srangfdhbcd7ygiip3phxx6cscbrpip3-file2.txt1770 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1771 Compression: zstd1772 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1773 NarSize: 1601774 References: 1775 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1776 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1777 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1778 {"version":1,"root":{"type":"regular","size":44}}17792026/11/09 12:16:19 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1780--- PASS: TestNARDeduplicationMetadataUploadBug (10.84s)1781=== CONT TestClientErrorHandling/InvalidStorePath1782--- PASS: TestService_Rustfstest (10.38s)1783=== CONT TestClientErrorHandling/InvalidAuthToken17842026/11/09 12:16:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete17852026/11/09 12:16:20 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLmE3Y2M3NjJjLThhZDctNDQ5OC1iNDUyLTUwNjQzNTZhZTkyYngxNzk0MjI2NTc3ODM5OTQyMDAw parts=1217862026/11/09 12:16:20 INFO Received uploads request method=POST path=/api/pending_closures1787--- PASS: TestCompletedNarNotReofferedAcrossClosures (11.76s)1788=== CONT TestClientErrorHandling/ServerNotAvailable17892026/11/09 12:16:21 INFO Received uploads request method=POST path=/api/pending_closures17902026/11/09 12:16:21 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/present17912026/11/09 12:16:21 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst17922026/11/09 12:16:21 INFO Received uploads request method=POST path=/api/pending_closures1793--- PASS: TestPresignedUploadRegisteredBeforeCommit (10.22s)1794=== CONT TestCacheConfigHandler/full_config,_no_issuer1795=== CONT TestCacheConfigHandler/no_signing_keys1796=== CONT TestCacheConfigHandler/no_cache_url_configured1797--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (11.68s)1798=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1799=== CONT TestProxyWriteTimeout/narinfo1800--- PASS: TestCacheConfigHandler (0.00s)1801 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1802 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1803 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1804 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1805=== CONT TestProxyWriteTimeout/10_GiB_nar18062026/11/09 12:16:21 WARN Request failed, retrying attempt=2 backoff=183.522896ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1807=== CONT TestProxyWriteTimeout/1_GiB_nar1808=== CONT TestProxyWriteTimeout/unknown_size1809=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1810=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1811--- PASS: TestProxyWriteTimeout (0.00s)1812 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1813 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1814 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1815 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)18162026/11/09 12:16:21 WARN Request failed, retrying attempt=3 backoff=431.421522ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18172026/11/09 12:16:21 WARN readiness check failed error="closed pool"1818--- PASS: TestService_readinessHandler (10.11s)1819=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed18202026/11/09 12:16:21 INFO Received uploads request method=POST path=/api/pending_closures18212026/11/09 12:16:21 INFO Received uploads request method=POST path=/api/pending_closures18222026/11/09 12:16:21 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18232026/11/09 12:16:21 INFO Uploading 4y4bp4115v5vd79ryanif7xmkprrh61p-a (256B)18242026/11/09 12:16:21 INFO Uploading zmrp36qpisn6vw2wmzp070l84p7vsxr8-shared-dep (136B)18252026/11/09 12:16:21 WARN Failed to register uploaded object key=zmrp36qpisn6vw2wmzp070l84p7vsxr8.ls error="server returned 404: 404 page not found\n"18262026/11/09 12:16:21 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18272026/11/09 12:16:21 WARN Failed to register uploaded object key=nar/09xwcsfabq4b5vh6nb0fc4dmz1gxbx1wwqsqy52ykf14dv0zgl3b.nar.zst error="server returned 404: 404 page not found\n"18282026/11/09 12:16:21 WARN Failed to register uploaded object key=4y4bp4115v5vd79ryanif7xmkprrh61p.ls error="server returned 404: 404 page not found\n"18292026/11/09 12:16:21 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign18302026/11/09 12:16:21 WARN Failed to register uploaded object key=014pvs7msglwmqgd0riymxw7g2zzibpw.ls error="server returned 404: 404 page not found\n"18312026/11/09 12:16:21 INFO Signed narinfos id=1 count=218322026/11/09 12:16:21 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign18332026/11/09 12:16:21 INFO Signed narinfos id=2 count=218342026/11/09 12:16:21 INFO Uploading 4 narinfos18352026/11/09 12:16:21 WARN Request failed, retrying attempt=4 backoff=842.08205ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present18362026/11/09 12:16:21 WARN Failed to register uploaded object key=4y4bp4115v5vd79ryanif7xmkprrh61p.narinfo error="server returned 404: 404 page not found\n"18372026/11/09 12:16:21 WARN Failed to register uploaded object key=zmrp36qpisn6vw2wmzp070l84p7vsxr8.narinfo error="server returned 404: 404 page not found\n"18382026/11/09 12:16:21 WARN Failed to register uploaded object key=014pvs7msglwmqgd0riymxw7g2zzibpw.narinfo error="server returned 404: 404 page not found\n"18392026/11/09 12:16:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18402026/11/09 12:16:22 WARN Failed to register uploaded object key=zmrp36qpisn6vw2wmzp070l84p7vsxr8.narinfo error="server returned 404: 404 page not found\n"18412026/11/09 12:16:22 INFO Completed upload id=1 objects=6 duration=43.081625ms18422026/11/09 12:16:22 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18432026/11/09 12:16:22 INFO Completed upload id=2 objects=6 duration=1.11875ms18442026/11/09 12:16:22 INFO Upload complete. (676ms)1845=== NAME TestClientFallsBackToClosures1846 client_pushes_test.go:112: Retrieved narinfo from S3:1847 StorePath: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientFallsBackToClosures1416256147/001/store/zmrp36qpisn6vw2wmzp070l84p7vsxr8-shared-dep1848 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1849 Compression: zstd1850 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821851 NarSize: 1361852 References: 1853 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1854 client_pushes_test.go:112: Retrieved narinfo from S3:1855 StorePath: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientFallsBackToClosures1416256147/001/store/4y4bp4115v5vd79ryanif7xmkprrh61p-a1856 URL: nar/09xwcsfabq4b5vh6nb0fc4dmz1gxbx1wwqsqy52ykf14dv0zgl3b.nar.zst1857 Compression: zstd1858 NarHash: sha256:09xwcsfabq4b5vh6nb0fc4dmz1gxbx1wwqsqy52ykf14dv0zgl3b1859 NarSize: 2561860 References: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientFallsBackToClosures1416256147/001/store/zmrp36qpisn6vw2wmzp070l84p7vsxr8-shared-dep1861 CA: text:sha256:1s1bxcaj597yaalzhrp63q66zl3458vj5wh4fhs5c8hch3fid88h1862 client_pushes_test.go:112: Retrieved narinfo from S3:1863 StorePath: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientFallsBackToClosures1416256147/001/store/014pvs7msglwmqgd0riymxw7g2zzibpw-b1864 URL: nar/09xwcsfabq4b5vh6nb0fc4dmz1gxbx1wwqsqy52ykf14dv0zgl3b.nar.zst1865 Compression: zstd1866 NarHash: sha256:09xwcsfabq4b5vh6nb0fc4dmz1gxbx1wwqsqy52ykf14dv0zgl3b1867 NarSize: 2561868 References: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientFallsBackToClosures1416256147/001/store/zmrp36qpisn6vw2wmzp070l84p7vsxr8-shared-dep1869 CA: text:sha256:1s1bxcaj597yaalzhrp63q66zl3458vj5wh4fhs5c8hch3fid88h1870--- PASS: TestClientFallsBackToClosures (12.05s)1871=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost18722026/11/09 12:16:22 WARN Rate limiter enabled after throttle name=s3-test rate=518732026/11/09 12:16:22 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1874=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1875 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101876 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001877--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (12.94s)1878=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed18792026/11/09 12:16:22 INFO Received push request method=POST path=/api/pushes18802026/11/09 12:16:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18812026/11/09 12:16:22 INFO Signed narinfos id=1 count=118822026/11/09 12:16:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18832026/11/09 12:16:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18842026/11/09 12:16:22 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"18852026/11/09 12:16:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18862026/11/09 12:16:22 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"18872026/11/09 12:16:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18882026/11/09 12:16:22 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=118892026/11/09 12:16:22 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18902026/11/09 12:16:22 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1891--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (10.76s)1892=== CONT TestResolveDBConnectionString/flag_wins1893=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1894=== CONT TestResolveDBConnectionString/nothing_configured1895=== CONT TestResolveDBConnectionString/missing_file_is_an_error1896=== CONT TestResolveDBConnectionString/file_when_flag_empty1897=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18982026/11/09 12:16:22 INFO Received complete multipart upload request method=POST path=/1899--- PASS: TestResolveDBConnectionString (0.00s)1900 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1901 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1902 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1903 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1904 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1905=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info19062026/11/09 12:16:22 INFO Received uploads request method=POST path=/1907=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure19082026/11/09 12:16:22 INFO Received uploads request method=POST path=/1909--- PASS: TestService_healthCheckHandler (10.92s)1910=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts19112026/11/09 12:16:22 INFO Received request for more parts method=POST path=/19122026/11/09 12:16:22 WARN Request failed, retrying attempt=5 backoff=1.73860402s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1913=== CONT TestIsValidUploadKey/narinfo1914=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key19152026/11/09 12:16:22 INFO Received request for more parts method=POST path=/1916=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key19172026/11/09 12:16:22 INFO Received complete multipart upload request method=POST path=/1918=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal19192026/11/09 12:16:22 INFO Received uploads request method=POST path=/1920--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1921 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1922 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1923 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1924 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1925=== CONT TestPendingClosureWriteTimeout/empty1926=== CONT TestIsValidUploadKey/unknown_type1927=== CONT TestIsValidUploadKey/empty_key1928=== CONT TestIsValidUploadKey/absolute1929=== CONT TestIsValidUploadKey/traversal_nar1930=== CONT TestIsValidUploadKey/traversal1931=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1932=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1933=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1934=== CONT TestIsValidUploadKey/index.html1935=== CONT TestIsValidUploadKey/nix-cache-info1936=== CONT TestIsValidUploadKey/realisation_plus_in_output1937=== CONT TestIsValidUploadKey/realisation1938=== CONT TestIsValidUploadKey/build_log_equals1939=== CONT TestIsValidUploadKey/build_log_question_mark1940=== CONT TestIsValidUploadKey/build_log_plus_in_name1941=== CONT TestIsValidUploadKey/build_log_home-manager_file1942=== CONT TestIsValidUploadKey/build_log1943=== CONT TestIsValidUploadKey/listing1944=== CONT TestIsValidUploadKey/nar_plain1945=== CONT TestIsValidUploadKey/nar_xz1946=== CONT TestIsValidUploadKey/nar_zst1947--- PASS: TestIsValidUploadKey (0.00s)1948 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1949 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1950 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1951 --- PASS: TestIsValidUploadKey/absolute (0.00s)1952 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1953 --- PASS: TestIsValidUploadKey/traversal (0.00s)1954 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1955 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1956 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1957 --- PASS: TestIsValidUploadKey/index.html (0.00s)1958 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1959 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1960 --- PASS: TestIsValidUploadKey/realisation (0.00s)1961 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1962 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1963 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1964 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1965 --- PASS: TestIsValidUploadKey/build_log (0.00s)1966 --- PASS: TestIsValidUploadKey/listing (0.00s)1967 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1968 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1969 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1970=== CONT TestPendingClosureWriteTimeout/670k_objects1971=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline19722026/11/09 12:16:22 INFO Received push request method=POST path=/api/pushes19732026/11/09 12:16:22 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)19742026/11/09 12:16:22 INFO Uploading m8whfamgvhs0lrb85m1am3qmf6wmy6m4-shared-dep (136B)19752026/11/09 12:16:22 INFO Uploading m77xr2a8lsb67ii9r86cxyvg17yjh3x6-a (256B)19762026/11/09 12:16:23 WARN Failed to register uploaded object key=zjyp08b5fqvyaxipwjh6r9snk0w6fwyd.ls error="server returned 404: 404 page not found\n"19772026/11/09 12:16:23 WARN Failed to register uploaded object key=m8whfamgvhs0lrb85m1am3qmf6wmy6m4.ls error="server returned 404: 404 page not found\n"19782026/11/09 12:16:23 WARN Failed to register uploaded object key=m77xr2a8lsb67ii9r86cxyvg17yjh3x6.ls error="server returned 404: 404 page not found\n"19792026/11/09 12:16:23 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"19802026/11/09 12:16:23 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19812026/11/09 12:16:23 WARN Failed to register uploaded object key=nar/19fg0acbhriksh6ggcbd2h3wws71smj741pkvrpkhf0vshv53vd5.nar.zst error="server returned 404: 404 page not found\n"19822026/11/09 12:16:23 INFO Signed narinfos id=1 count=319832026/11/09 12:16:23 INFO Uploading 3 narinfos19842026/11/09 12:16:23 INFO Received uploads request method=POST path=/api/pending_closures19852026/11/09 12:16:23 WARN Failed to register uploaded object key=zjyp08b5fqvyaxipwjh6r9snk0w6fwyd.narinfo error="server returned 404: 404 page not found\n"19862026/11/09 12:16:23 WARN Failed to register uploaded object key=m77xr2a8lsb67ii9r86cxyvg17yjh3x6.narinfo error="server returned 404: 404 page not found\n"19872026/11/09 12:16:23 INFO Received complete push request method=POST path=/api/pushes/1/complete1988--- PASS: TestUploadHandlersRejectOversizedBody (0.17s)1989 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.04s)1990 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.05s)1991 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.64s)19922026/11/09 12:16:23 WARN Failed to register uploaded object key=m8whfamgvhs0lrb85m1am3qmf6wmy6m4.narinfo error="server returned 404: 404 page not found\n"1993=== CONT TestPendingClosureWriteTimeout/400_objects1994=== CONT TestService_RequireScope_OIDC/builder_may_write1995=== CONT TestService_RequireScope_OIDC/reader_may_read1996=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1997=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19982026/11/09 12:16:23 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]1999=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2000=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2001=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2002=== CONT TestService_RequireScope_OIDC/writer_implies_read2003=== CONT TestService_RequireScope_OIDC/reader_may_not_write2004=== CONT TestService_RequireScope_OIDC/static_token_may_write2005=== CONT TestService_RequireScope_OIDC/static_token_may_admin2006=== CONT TestService_RequireScope_OIDC/ops_may_admin2007=== CONT TestService_RequireScope_OIDC/ops_may_not_write2008=== CONT TestService_RequireScope_OIDC/builder_may_not_admin20092026/11/09 12:16:23 INFO Completed push id=1 objects=8 duration=193.3115ms2010=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token20112026/11/09 12:16:23 INFO Upload complete. (685ms)2012--- PASS: TestService_RequireScope_OIDC (8.78s)2013 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2014 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2015 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2016 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2017 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2018 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2019 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2020 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2021 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2022 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2023 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2024 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2025 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2026 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2027=== NAME TestClientPushesUseOnePush2028 client_pushes_test.go:97: Retrieved narinfo from S3:2029 StorePath: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientPushesUseOnePush1813394399/001/store/m8whfamgvhs0lrb85m1am3qmf6wmy6m4-shared-dep2030 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst2031 Compression: zstd2032=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20332026/11/09 12:16:23 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]2034=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2035=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2036=== NAME TestClientPushesUseOnePush2037 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y822038 NarSize: 13620392026/11/09 12:16:23 WARN Authentication failed token_preview=eyJhbGciOi...7avSwlyZqg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2040 References: 2041 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n2042 client_pushes_test.go:97: Retrieved narinfo from S3:2043 StorePath: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientPushesUseOnePush1813394399/001/store/m77xr2a8lsb67ii9r86cxyvg17yjh3x6-a2044 URL: nar/19fg0acbhriksh6ggcbd2h3wws71smj741pkvrpkhf0vshv53vd5.nar.zst2045--- PASS: TestService_AuthMiddleware_OIDC (8.83s)2046 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2047 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2048 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2049 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.02s)2050=== NAME TestClientPushesUseOnePush2051 Compression: zstd2052 NarHash: sha256:19fg0acbhriksh6ggcbd2h3wws71smj741pkvrpkhf0vshv53vd52053 NarSize: 2562054 References: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientPushesUseOnePush1813394399/001/store/m8whfamgvhs0lrb85m1am3qmf6wmy6m4-shared-dep2055 CA: text:sha256:07lm5fqwivy6f1z5sg8m89y6bh01n8sj4a6rx36lch6pwwrd1bk82056 client_pushes_test.go:97: Retrieved narinfo from S3:2057 StorePath: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientPushesUseOnePush1813394399/001/store/zjyp08b5fqvyaxipwjh6r9snk0w6fwyd-b2058 URL: nar/19fg0acbhriksh6ggcbd2h3wws71smj741pkvrpkhf0vshv53vd5.nar.zst2059 Compression: zstd2060 NarHash: sha256:19fg0acbhriksh6ggcbd2h3wws71smj741pkvrpkhf0vshv53vd52061 NarSize: 2562062 References: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestClientPushesUseOnePush1813394399/001/store/m8whfamgvhs0lrb85m1am3qmf6wmy6m4-shared-dep2063 CA: text:sha256:07lm5fqwivy6f1z5sg8m89y6bh01n8sj4a6rx36lch6pwwrd1bk82064--- PASS: TestClientPushesUseOnePush (12.26s)20652026/11/09 12:16:23 INFO Received uploads request method=POST path=/api/pending_closures20662026/11/09 12:16:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete20672026/11/09 12:16:23 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLjAxYmMwMWY1LTBjZWMtNDAyYS05Yzc0LWQ1NTUzYWY5YzA5OXgxNzk0MjI2NTgzMzY5MzYwMDAw20682026/11/09 12:16:23 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLjAxYmMwMWY1LTBjZWMtNDAyYS05Yzc0LWQ1NTUzYWY5YzA5OXgxNzk0MjI2NTgzMzY5MzYwMDAw parts=12069--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (11.57s)20702026/11/09 12:16:23 INFO Received uploads request method=POST path=/api/pending_closures20712026/11/09 12:16:24 INFO Received push request method=POST path=/api/pushes20722026/11/09 12:16:24 INFO Received complete push request method=POST path=/api/pushes/1/complete20732026/11/09 12:16:24 INFO Completed push id=1 objects=4 duration=34.300792ms20742026/11/09 12:16:24 INFO Received push request method=POST path=/api/pushes20752026/11/09 12:16:24 INFO Aborted multipart uploads count=0 kept=020762026/11/09 12:16:24 WARN Force mode enabled - objects will be deleted immediately without grace period20772026/11/09 12:16:24 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=020782026/11/09 12:16:24 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-config20792026/11/09 12:16:24 INFO Vacuumed table table=pending_closures20802026/11/09 12:16:24 INFO Vacuumed table table=pending_objects20812026/11/09 12:16:24 WARN Request failed, retrying attempt=2 backoff=215.064785ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config20822026/11/09 12:16:24 INFO Vacuumed table table=multipart_uploads2083=== RUN TestPush_RejectsBadRequests/no_roots2084=== PAUSE TestPush_RejectsBadRequests/no_roots2085=== RUN TestPush_RejectsBadRequests/no_objects2086=== PAUSE TestPush_RejectsBadRequests/no_objects2087=== RUN TestPush_RejectsBadRequests/bad_root2088=== PAUSE TestPush_RejectsBadRequests/bad_root2089=== RUN TestPush_RejectsBadRequests/root_not_in_objects2090=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects2091=== CONT TestPush_RejectsBadRequests/no_roots20922026/11/09 12:16:24 INFO Received push request method=POST path=/api/pushes2093=== CONT TestPush_RejectsBadRequests/bad_root20942026/11/09 12:16:24 INFO Received push request method=POST path=/api/pushes2095=== CONT TestPush_RejectsBadRequests/no_objects20962026/11/09 12:16:24 INFO Received push request method=POST path=/api/pushes2097=== CONT TestPush_RejectsBadRequests/root_not_in_objects20982026/11/09 12:16:24 INFO Received push request method=POST path=/api/pushes2099--- PASS: TestPush_RejectsBadRequests (10.71s)2100 --- PASS: TestPush_RejectsBadRequests/no_roots (0.01s)2101 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2102 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2103 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)21042026/11/09 12:16:24 INFO Vacuumed table table=closures21052026/11/09 12:16:24 INFO Vacuumed table table=objects21062026/11/09 12:16:24 INFO Received complete push request method=POST path=/api/pushes/2/complete21072026/11/09 12:16:24 INFO Completed push id=2 objects=4 duration=7.764375ms2108--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (11.12s)21092026/11/09 12:16:24 WARN Request failed, retrying attempt=3 backoff=366.206657ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21102026/11/09 12:16:25 WARN Request failed, retrying attempt=4 backoff=818.783855ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21112026/11/09 12:16:25 INFO Aborted multipart uploads count=0 kept=021122026/11/09 12:16:25 WARN Force mode enabled - objects will be deleted immediately without grace period21132026-11-09 12:16:25.800 UTC [62979] ERROR: canceling statement due to user request21142026-11-09 12:16:25.800 UTC [62979] CONTEXT: while locking tuple (0,1) in relation "objects"21152026-11-09 12:16:25.800 UTC [62979] STATEMENT: -- name: MarkStaleObjects :execrows2116 WITH RECURSIVE ct AS (2117 SELECT timezone('UTC', now()) AS now2118 ),2119 closure_reach AS (2120 -- Start with all closure keys2121 SELECT o.key, o.refs2122 FROM objects o2123 INNER JOIN closures c ON o.key = c.key2124 UNION2125 -- Recursively add all referenced objects2126 SELECT o.key, o.refs2127 FROM objects o2128 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2129 ),2130 reachable_objects AS (2131 SELECT DISTINCT key FROM closure_reach2132 ),2133 stale_objects AS (2134 SELECT o.key2135 FROM objects AS o, ct2136 WHERE2137 NOT EXISTS (2138 SELECT 12139 FROM reachable_objects ro2140 WHERE ro.key = o.key2141 )2142 AND NOT EXISTS (2143 SELECT 12144 FROM pending_objects AS po2145 WHERE po.key = o.key2146 )2147 AND o.deleted_at IS NULL -- Only mark fresh objects2148 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2149 FOR UPDATE2150 )2151 UPDATE objects2152 SET2153 deleted_at = ct.now,2154 first_deleted_at = COALESCE(first_deleted_at, ct.now)2155 FROM stale_objects, ct2156 WHERE objects.key = stale_objects.key2157 21582026/11/09 12:16:26 WARN Request failed, retrying attempt=5 backoff=1.525876888s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21592026/11/09 12:16:26 INFO Aborted multipart uploads count=0 kept=021602026/11/09 12:16:26 WARN Force mode enabled - objects will be deleted immediately without grace period21612026/11/09 12:16:26 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:51514/bucket94/?delete=\": context canceled"2162--- PASS: TestGCEndsOnShutdown (0.00s)2163 --- PASS: TestGCEndsOnShutdown/before_the_run (10.68s)2164 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (10.63s)2165 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (9.91s)21662026/11/09 12:16:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2167--- PASS: TestDeleteClosuresRacingPins (16.59s)21682026/11/09 12:16:26 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLmU5ODFhYTFlLTA3YjgtNGJjOS04YmRmLWJkYTk2MWU1MTJkN3gxNzk0MjI2NTgzODA0OTA4MDAw parts=1221692026/11/09 12:16:27 INFO Received uploads request method=POST path=/api/pending_closures21702026/11/09 12:16:27 INFO Aborted multipart uploads count=0 kept=021712026/11/09 12:16:27 WARN Force mode enabled - objects will be deleted immediately without grace period2172--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.01s)2173 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (10.17s)2174 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (9.36s)21752026/11/09 12:16:27 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=021762026/11/09 12:16:27 INFO Vacuumed table table=pending_closures21772026/11/09 12:16:27 INFO Vacuumed table table=pending_objects21782026/11/09 12:16:27 INFO Vacuumed table table=multipart_uploads21792026/11/09 12:16:27 INFO Vacuumed table table=closures21802026/11/09 12:16:27 INFO Received uploads request method=POST path=/api/pending_closures21812026/11/09 12:16:27 INFO Vacuumed table table=objects21822026/11/09 12:16:27 INFO Aborted multipart uploads count=0 kept=021832026/11/09 12:16:27 WARN Force mode enabled - objects will be deleted immediately without grace period21842026/11/09 12:16:27 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021852026/11/09 12:16:27 INFO Vacuumed table table=pending_closures21862026/11/09 12:16:27 INFO Vacuumed table table=pending_objects21872026/11/09 12:16:27 INFO Vacuumed table table=multipart_uploads21882026/11/09 12:16:27 INFO Vacuumed table table=closures21892026/11/09 12:16:27 INFO Vacuumed table table=objects2190--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2191 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (8.98s)2192 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (8.85s)21932026/11/09 12:16:27 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"21942026/11/09 12:16:27 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-config21952026/11/09 12:16:27 WARN Request failed, retrying attempt=2 backoff=210.203131ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21962026/11/09 12:16:28 WARN Request failed, retrying attempt=3 backoff=383.240295ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21972026/11/09 12:16:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21982026/11/09 12:16:28 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLmYwZWU2Mjg2LTk1OTgtNGEyNC1iNzYwLTRkNDU2MzMwMzU3MHgxNzk0MjI2NTgzODQ4NDY4MDAw parts=122199--- PASS: TestSharedNarBothUploadsComplete (14.68s)22002026/11/09 12:16:28 INFO Received uploads request method=POST path=/api/pending_closures22012026/11/09 12:16:28 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22022026/11/09 12:16:28 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22032026/11/09 12:16:28 WARN Request failed, retrying attempt=4 backoff=759.149024ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22042026/11/09 12:16:28 INFO Received uploads request method=POST path=/api/pending_closures22052026/11/09 12:16:28 INFO Received uploads request method=POST path=/api/pending_closures22062026/11/09 12:16:29 WARN Request failed, retrying attempt=5 backoff=1.725351066s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22072026/11/09 12:16:29 INFO Received uploads request method=POST path=/api/pending_closures22082026/11/09 12:16:29 INFO Received uploads request method=POST path=/api/pending_closures22092026/11/09 12:16:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22102026/11/09 12:16:30 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLjJmZWYzN2NhLTBjZDMtNDZlMi1hZmM2LWNiY2ZkMGI1YTEzMngxNzk0MjI2NTg4MjAzNjUxMDAw parts=1022112026/11/09 12:16:30 INFO Received uploads request method=POST path=/api/pending_closures22122026/11/09 12:16:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22132026/11/09 12:16:30 INFO Completed upload id=1 objects=3 duration=21.129458ms22142026/11/09 12:16:30 INFO Received uploads request method=POST path=/api/pending_closures22152026/11/09 12:16:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22162026/11/09 12:16:30 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLmM4OTBmZThkLWQzMDMtNDJjNS1iYTMwLWVmY2U5NjVmZTAzMngxNzk0MjI2NTg4NDU5NzExMDAw parts=1022172026/11/09 12:16:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22182026/11/09 12:16:30 INFO Completed upload id=1 objects=3 duration=18.658375ms22192026/11/09 12:16:30 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_closures22202026/11/09 12:16:31 WARN Request failed, retrying attempt=2 backoff=199.162839ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22212026/11/09 12:16:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2222--- PASS: TestPendingClosureWriteTimeout (0.00s)2223 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2224 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2225 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2226 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (8.38s)22272026/11/09 12:16:31 WARN Request failed, retrying attempt=3 backoff=436.570567ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22282026/11/09 12:16:31 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLjQ4MzhlNWQ2LTNjZjgtNGFlMC1iNjBkLWJlOTYzODg3ZTUwMXgxNzk0MjI2NTg4ODYwMjAyMDAw parts=1022292026/11/09 12:16:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22302026/11/09 12:16:31 INFO Completed upload id=1 objects=3 duration=22.377958ms22312026/11/09 12:16:31 INFO Received uploads request method=POST path=/api/pending_closures22322026/11/09 12:16:31 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst22332026/11/09 12:16:31 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo22342026/11/09 12:16:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22352026/11/09 12:16:31 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLjQxNjJlNjIxLTAxNGUtNDMzYS05N2NkLWRiOTY3MGU4ZTdiZHgxNzk0MjI2NTg5MzIwODQyMDAw parts=1022362026/11/09 12:16:31 WARN Request failed, retrying attempt=4 backoff=831.905329ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22372026/11/09 12:16:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22382026/11/09 12:16:31 INFO Completed upload id=1 objects=3 duration=9.641875ms22392026/11/09 12:16:31 INFO Received uploads request method=POST path=/api/pending_closures22402026/11/09 12:16:31 INFO Received uploads request method=POST path=/api/pending_closures22412026/11/09 12:16:31 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22422026/11/09 12:16:31 WARN Found objects in DB but missing from S3, will re-upload count=122432026/11/09 12:16:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22442026/11/09 12:16:32 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLjAwY2Q1MjY5LTg0NjMtNGZhOC04YjZmLTA5ZGNiOGVhMzgxMHgxNzk0MjI2NTg5NzY2NTU5MDAw parts=1022452026/11/09 12:16:32 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22462026/11/09 12:16:32 INFO Completed upload id=1 objects=3 duration=32.2555ms22472026/11/09 12:16:32 INFO Received uploads request method=POST path=/api/pending_closures22482026/11/09 12:16:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22492026/11/09 12:16:32 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLjc0ODZjNzg0LWMyN2YtNGE2YS1iMjM4LTc1ODUwODExZWJlNngxNzk0MjI2NTkwNDMyNDI0MDAw parts=1022502026/11/09 12:16:32 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22512026/11/09 12:16:32 INFO Completed upload id=2 objects=3 duration=806.958µs22522026/11/09 12:16:32 WARN Request failed, retrying attempt=5 backoff=1.474856537s 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:16:32 INFO Received uploads request method=POST path=/api/pending_closures22542026/11/09 12:16:32 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22552026/11/09 12:16:32 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22562026/11/09 12:16:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22572026/11/09 12:16:33 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=ZWM5OWM4OTYtODFkNi00MjZkLTlhYmUtY2VhM2JlNTZkZjYwLjEzMzk4YzQ3LWE0NDgtNDFhYi05N2ZmLWU1ZmQzNzVlZWM2OXgxNzk0MjI2NTkyMTYyOTU2MDAw parts=1022582026/11/09 12:16:33 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22592026/11/09 12:16:33 INFO Completed upload id=2 objects=3 duration=854.75µs22602026/11/09 12:16:33 INFO Received uploads request method=POST path=/api/pending_closures22612026/11/09 12:16:33 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22622026/11/09 12:16:33 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2263--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.01s)2264 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (10.28s)2265 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (9.49s)2266 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (10.42s)2267 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (11.45s)2268 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (11.57s)2269--- PASS: TestClientErrorHandling (0.00s)2270 --- PASS: TestClientErrorHandling/InvalidStorePath (8.35s)2271 --- PASS: TestClientErrorHandling/InvalidAuthToken (8.17s)2272 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.38s)2273=== NAME TestOrphanedObjectsGCStressTest2274 orphaned_objects_gc_test.go:503: Stress test completed successfully:2275 orphaned_objects_gc_test.go:504: - Active objects preserved: 202276 orphaned_objects_gc_test.go:505: - Objects deleted: 2102277 orphaned_objects_gc_test.go:506: - Total GC'd: 2102278--- PASS: TestOrphanedObjectsGCStressTest (46.74s)2279PASS2280{"timestamp":"2026-11-09T12:16:39.146101Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51856","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)"}2281{"timestamp":"2026-11-09T12:16:39.146036Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:52034","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(5)"}2282{"timestamp":"2026-11-09T12:16:39.147183Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51785","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(2)"}22832026-11-09 12:16:39.302 UTC [62293] LOG: received smart shutdown request22842026-11-09 12:16:39.305 UTC [62293] LOG: background worker "logical replication launcher" (PID 62310) exited with exit code 122852026-11-09 12:16:39.315 UTC [62304] LOG: shutting down22862026-11-09 12:16:39.315 UTC [62304] LOG: checkpoint starting: shutdown immediate22872026-11-09 12:16:41.683 UTC [62304] LOG: checkpoint complete: wrote 11827 buffers (72.2%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=1.186 s, sync=1.152 s, total=2.368 s; sync files=36061, longest=0.011 s, average=0.001 s; distance=529922 kB, estimate=529922 kB; lsn=0/21D0DB28, redo lsn=0/21D0DB2822882026-11-09 12:16:41.721 UTC [62293] LOG: database system is shut down2289Running OIDC tests...2290=== RUN TestAudienceForIssuer2291=== PAUSE TestAudienceForIssuer2292=== RUN TestGlobMatch2293=== PAUSE TestGlobMatch2294=== RUN TestValidateToken_ValidToken2295=== PAUSE TestValidateToken_ValidToken2296=== RUN TestValidateToken_WrongAudience2297=== PAUSE TestValidateToken_WrongAudience2298=== RUN TestValidateToken_Expired2299=== PAUSE TestValidateToken_Expired2300=== RUN TestValidateToken_BoundClaimsMismatch2301=== PAUSE TestValidateToken_BoundClaimsMismatch2302=== RUN TestValidateToken_BoundSubjectMismatch2303=== PAUSE TestValidateToken_BoundSubjectMismatch2304=== RUN TestValidateToken_MultipleProviders2305=== PAUSE TestValidateToken_MultipleProviders2306=== RUN TestValidateToken_NoMatchingProvider2307=== PAUSE TestValidateToken_NoMatchingProvider2308=== RUN TestValidateToken_KubernetesServiceAccount2309=== PAUSE TestValidateToken_KubernetesServiceAccount2310=== RUN TestNewValidator_KubernetesRequiresCA2311=== PAUSE TestNewValidator_KubernetesRequiresCA2312=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2313=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2314=== RUN TestPins_ReservedForMatchingRule2315=== PAUSE TestPins_ReservedForMatchingRule2316=== RUN TestPins_TopLevelShorthand2317=== PAUSE TestPins_TopLevelShorthand2318=== RUN TestPins_ConfigValidation2319=== PAUSE TestPins_ConfigValidation2320=== RUN TestScopes_LegacyProviderDefaultsToWrite2321=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2322=== RUN TestScopes_Rules2323=== PAUSE TestScopes_Rules2324=== RUN TestScopes_ConfigValidation2325=== PAUSE TestScopes_ConfigValidation2326=== CONT TestAudienceForIssuer2327--- PASS: TestAudienceForIssuer (0.00s)2328=== CONT TestValidateToken_BoundClaimsMismatch2329=== CONT TestValidateToken_KubernetesServiceAccount2330=== CONT TestValidateToken_WrongAudience2331=== CONT TestValidateToken_ValidToken2332=== CONT TestGlobMatch2333=== RUN TestGlobMatch/foo_foo2334=== PAUSE TestGlobMatch/foo_foo2335=== CONT TestValidateToken_Expired2336=== RUN TestGlobMatch/foo_bar2337=== PAUSE TestGlobMatch/foo_bar2338=== RUN TestGlobMatch/*_2339=== PAUSE TestGlobMatch/*_2340=== RUN TestGlobMatch/*_anything2341=== PAUSE TestGlobMatch/*_anything2342=== RUN TestGlobMatch/foo*_foo2343=== PAUSE TestGlobMatch/foo*_foo2344=== RUN TestGlobMatch/foo*_foobar2345=== PAUSE TestGlobMatch/foo*_foobar2346=== RUN TestGlobMatch/foo*_bar2347=== PAUSE TestGlobMatch/foo*_bar2348=== RUN TestGlobMatch/*bar_bar2349=== PAUSE TestGlobMatch/*bar_bar2350=== RUN TestGlobMatch/*bar_foobar2351=== PAUSE TestGlobMatch/*bar_foobar2352=== RUN TestGlobMatch/*bar_foo2353=== PAUSE TestGlobMatch/*bar_foo2354=== RUN TestGlobMatch/foo*bar_foobar2355=== PAUSE TestGlobMatch/foo*bar_foobar2356=== RUN TestGlobMatch/foo*bar_foo123bar2357=== PAUSE TestGlobMatch/foo*bar_foo123bar2358=== RUN TestGlobMatch/foo*bar_foobarbaz2359=== PAUSE TestGlobMatch/foo*bar_foobarbaz2360=== RUN TestGlobMatch/*/*_foo/bar2361=== PAUSE TestGlobMatch/*/*_foo/bar2362=== RUN TestGlobMatch/*/*_foo2363=== PAUSE TestGlobMatch/*/*_foo2364=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2365=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2366=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02367=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02368=== RUN TestGlobMatch/refs/*/main_refs/heads/main2369=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2370=== RUN TestGlobMatch/fo?_foo2371=== PAUSE TestGlobMatch/fo?_foo2372=== RUN TestGlobMatch/fo?_fo2373=== PAUSE TestGlobMatch/fo?_fo2374=== RUN TestGlobMatch/fo?_fooo2375=== PAUSE TestGlobMatch/fo?_fooo2376=== RUN TestGlobMatch/?oo_foo2377=== PAUSE TestGlobMatch/?oo_foo2378=== RUN TestGlobMatch/?oo_boo2379=== PAUSE TestGlobMatch/?oo_boo2380=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2381=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2382=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2383=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2384=== CONT TestGlobMatch/foo_foo2385=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2386=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2387=== CONT TestGlobMatch/?oo_boo2388=== CONT TestGlobMatch/fo?_fo2389=== CONT TestGlobMatch/foo*_bar2390=== CONT TestGlobMatch/foo*_foobar2391=== CONT TestGlobMatch/foo*_foo2392=== CONT TestGlobMatch/*_anything2393=== CONT TestGlobMatch/*_2394=== CONT TestGlobMatch/foo_bar2395=== CONT TestValidateToken_MultipleProviders2396=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2397=== CONT TestGlobMatch/fo?_foo2398=== CONT TestGlobMatch/refs/*/main_refs/heads/main2399=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02400=== CONT TestGlobMatch/*/*_foo/bar2401=== CONT TestGlobMatch/*/*_foo2402=== CONT TestGlobMatch/foo*bar_foobarbaz2403=== CONT TestValidateToken_NoMatchingProvider2404=== CONT TestPins_ConfigValidation2405=== CONT TestScopes_ConfigValidation2406--- PASS: TestScopes_ConfigValidation (0.00s)2407=== CONT TestScopes_Rules2408--- PASS: TestPins_ConfigValidation (0.01s)2409=== CONT TestScopes_LegacyProviderDefaultsToWrite2410=== CONT TestValidateToken_BoundSubjectMismatch2411=== CONT TestPins_ReservedForMatchingRule2412=== CONT TestPins_TopLevelShorthand2413=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2414=== CONT TestNewValidator_KubernetesRequiresCA2415=== CONT TestGlobMatch/foo*bar_foo123bar2416=== CONT TestGlobMatch/?oo_foo2417=== CONT TestGlobMatch/fo?_fooo2418=== CONT TestGlobMatch/foo*bar_foobar2419=== CONT TestGlobMatch/*bar_foo2420=== CONT TestGlobMatch/*bar_foobar2421=== CONT TestGlobMatch/*bar_bar2422--- PASS: TestGlobMatch (0.00s)2423 --- PASS: TestGlobMatch/foo_foo (0.00s)2424 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2425 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2426 --- PASS: TestGlobMatch/?oo_boo (0.00s)2427 --- PASS: TestGlobMatch/fo?_fo (0.00s)2428 --- PASS: TestGlobMatch/foo*_bar (0.00s)2429 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2430 --- PASS: TestGlobMatch/foo*_foo (0.00s)2431 --- PASS: TestGlobMatch/*_anything (0.00s)2432 --- PASS: TestGlobMatch/*_ (0.00s)2433 --- PASS: TestGlobMatch/foo_bar (0.00s)2434 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2435 --- PASS: TestGlobMatch/fo?_foo (0.00s)2436 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2437 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2438 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2439 --- PASS: TestGlobMatch/*/*_foo (0.00s)2440 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2441 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2442 --- PASS: TestGlobMatch/?oo_foo (0.00s)2443 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2444 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2445 --- PASS: TestGlobMatch/*bar_foo (0.00s)2446 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2447 --- PASS: TestGlobMatch/*bar_bar (0.00s)24482026/11/09 12:16:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52047/oidc24492026/11/09 12:16:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52049/oidc2450--- PASS: TestValidateToken_BoundClaimsMismatch (0.07s)2451--- PASS: TestValidateToken_Expired (0.07s)24522026/11/09 12:16:43 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5205124532026/11/09 12:16:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52053/oidc24542026/11/09 12:16:43 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52055/oidc2455--- PASS: TestValidateToken_WrongAudience (0.08s)2456--- PASS: TestPins_ReservedForMatchingRule (0.07s)24572026/11/09 12:16:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52057/oidc2458--- PASS: TestValidateToken_KubernetesServiceAccount (0.09s)2459--- PASS: TestValidateToken_ValidToken (0.11s)24602026/11/09 12:16:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52062/oidc24612026/11/09 12:16:44 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324622026/11/09 12:16:44 http: TLS handshake error from 127.0.0.1:52061: read tcp 127.0.0.1:52060->127.0.0.1:52061: use of closed network connection2463--- PASS: TestNewValidator_KubernetesRequiresCA (0.14s)2464--- PASS: TestPins_TopLevelShorthand (0.16s)24652026/11/09 12:16:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52067/oidc2466--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.16s)2467--- PASS: TestScopes_Rules (0.18s)24682026/11/09 12:16:44 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:52070/oidc24692026/11/09 12:16:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52046/oidc24702026/11/09 12:16:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52073/oidc24712026/11/09 12:16:44 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:52075/oidc2472--- PASS: TestValidateToken_MultipleProviders (0.30s)2473--- PASS: TestValidateToken_BoundSubjectMismatch (0.29s)2474--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.30s)24752026/11/09 12:16:44 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:52069/oidc2476--- PASS: TestValidateToken_NoMatchingProvider (0.39s)2477PASS2478Running hook tests...2479=== RUN TestSendPathsEmpty2480=== PAUSE TestSendPathsEmpty2481=== RUN TestQueueEnqueueAndFetch2482=== PAUSE TestQueueEnqueueAndFetch2483=== RUN TestQueueDeduplication2484=== PAUSE TestQueueDeduplication2485=== RUN TestQueueRemove2486=== PAUSE TestQueueRemove2487=== RUN TestQueueFetchBatchLimit2488=== PAUSE TestQueueFetchBatchLimit2489=== RUN TestQueueRetryMovesToBack2490=== PAUSE TestQueueRetryMovesToBack2491=== RUN TestQueueFetchRemoveLifecycle2492=== PAUSE TestQueueFetchRemoveLifecycle2493=== RUN TestQueueConcurrentWriters2494=== PAUSE TestQueueConcurrentWriters2495=== RUN TestQueueRemoveLargeClosure2496=== PAUSE TestQueueRemoveLargeClosure2497=== RUN TestServerClientIntegration2498--- PASS: TestServerClientIntegration (0.00s)2499=== RUN TestServerQueueError25002026/11/09 12:16:44 ERROR Failed to queue paths error="permission denied" count=12501--- PASS: TestServerQueueError (0.00s)2502=== RUN TestGetListenerSocketActivation2503 server_test.go:145: systemd socket activation does not exist on darwin2504--- SKIP: TestGetListenerSocketActivation (0.00s)2505=== RUN TestServerStalledClientDoesNotBlockShutdown2506=== PAUSE TestServerStalledClientDoesNotBlockShutdown2507=== RUN TestServerBacksOffOnAcceptErrors2508=== PAUSE TestServerBacksOffOnAcceptErrors2509=== RUN TestDrainIsolatesPoisonPath2510=== PAUSE TestDrainIsolatesPoisonPath2511=== RUN TestRunNotBlockedByPoisonHead2512=== PAUSE TestRunNotBlockedByPoisonHead2513=== RUN TestDrainGivesUpWhenServerDown2514=== PAUSE TestDrainGivesUpWhenServerDown2515=== RUN TestFailedPathPrunedByLaterClosure2516=== PAUSE TestFailedPathPrunedByLaterClosure2517=== RUN TestWorkerUploadsAndRemoves2518=== PAUSE TestWorkerUploadsAndRemoves2519=== RUN TestWorkerSkipsGCdPaths2520=== PAUSE TestWorkerSkipsGCdPaths2521=== RUN TestWorkerPrunesClosureDeps2522=== PAUSE TestWorkerPrunesClosureDeps2523=== RUN TestDrainTimeout2524=== PAUSE TestDrainTimeout2525=== RUN TestWorkerRemoveFailureIsNotProgress2526=== PAUSE TestWorkerRemoveFailureIsNotProgress2527=== RUN TestWorkerKeepsPathItCannotStat2528=== PAUSE TestWorkerKeepsPathItCannotStat2529=== CONT TestSendPathsEmpty2530=== CONT TestQueueEnqueueAndFetch2531--- PASS: TestSendPathsEmpty (0.00s)2532=== CONT TestWorkerKeepsPathItCannotStat2533=== CONT TestWorkerRemoveFailureIsNotProgress2534=== CONT TestDrainTimeout2535=== CONT TestWorkerPrunesClosureDeps2536=== CONT TestWorkerSkipsGCdPaths2537=== CONT TestWorkerUploadsAndRemoves2538=== CONT TestFailedPathPrunedByLaterClosure2539=== CONT TestDrainGivesUpWhenServerDown2540=== CONT TestRunNotBlockedByPoisonHead2541=== CONT TestQueueRemove2542=== CONT TestQueueRetryMovesToBack2543=== CONT TestQueueFetchBatchLimit2544=== CONT TestQueueFetchRemoveLifecycle2545=== CONT TestQueueDeduplication2546=== CONT TestServerBacksOffOnAcceptErrors25472026/11/09 12:16:44 ERROR Accept failed error="too many open files"2548=== CONT TestQueueRemoveLargeClosure2549=== CONT TestQueueConcurrentWriters2550=== CONT TestServerStalledClientDoesNotBlockShutdown2551=== CONT TestDrainIsolatesPoisonPath25522026/11/09 12:16:44 ERROR Accept failed error="too many open files"25532026/11/09 12:16:44 INFO Upload queue status pending=225542026/11/09 12:16:44 INFO Uploading batch count=125552026/11/09 12:16:44 INFO Uploading batch count=125562026/11/09 12:16:44 ERROR Upload failed error="upload failed" count=125572026/11/09 12:16:44 INFO Upload queue status pending=225582026/11/09 12:16:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestWorkerSkipsGCdPaths871949798/002/nonexistent2559--- PASS: TestQueueEnqueueAndFetch (0.02s)25602026/11/09 12:16:44 INFO Uploading batch count=125612026/11/09 12:16:44 INFO Uploading batch count=425622026/11/09 12:16:44 ERROR Upload failed error="upload failed" count=425632026/11/09 12:16:44 INFO Uploading batch count=125642026/11/09 12:16:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestDrainIsolatesPoisonPath2597974248/002/bbb25652026/11/09 12:16:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestWorkerRemoveFailureIsNotProgress919686825/002/nonexistent25662026/11/09 12:16:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12567--- PASS: TestQueueRemove (0.01s)25682026/11/09 12:16:44 INFO Uploading batch count=12569--- PASS: TestQueueFetchBatchLimit (0.01s)25702026/11/09 12:16:44 INFO Uploading batch count=225712026/11/09 12:16:44 INFO Upload queue status pending=325722026/11/09 12:16:44 INFO Upload queue status pending=225732026/11/09 12:16:44 INFO Uploading batch count=125742026/11/09 12:16:44 ERROR Upload failed error="upload failed" count=125752026/11/09 12:16:44 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestWorkerKeepsPathItCannotStat745546893/002/locked/aaa error="stat /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestWorkerKeepsPathItCannotStat745546893/002/locked/aaa: permission denied"25762026/11/09 12:16:44 INFO Uploading batch count=22577--- PASS: TestQueueRetryMovesToBack (0.02s)2578--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25792026/11/09 12:16:44 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestWorkerKeepsPathItCannotStat745546893/002/locked/aaa error="stat /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestWorkerKeepsPathItCannotStat745546893/002/locked/aaa: permission denied"25802026/11/09 12:16:44 WARN Cannot stat store path, will retry later path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestWorkerKeepsPathItCannotStat745546893/002/locked/aaa error="stat /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestWorkerKeepsPathItCannotStat745546893/002/locked/aaa: permission denied"25812026/11/09 12:16:44 INFO Uploading batch count=125822026/11/09 12:16:44 ERROR Upload failed error="upload failed" count=125832026/11/09 12:16:44 ERROR Drain finished with paths left in queue remaining=125842026/11/09 12:16:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestWorkerRemoveFailureIsNotProgress919686825/002/nonexistent25852026/11/09 12:16:44 INFO Uploading batch count=125862026/11/09 12:16:44 ERROR Upload failed error="upload failed" count=125872026/11/09 12:16:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125882026/11/09 12:16:44 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestWorkerRemoveFailureIsNotProgress919686825/002/nonexistent25892026/11/09 12:16:44 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=125902026/11/09 12:16:44 ERROR Drain finished with paths left in queue remaining=125912026/11/09 12:16:44 INFO Uploading batch count=225922026/11/09 12:16:44 ERROR Upload failed error="upload failed" count=225932026/11/09 12:16:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestDrainGivesUpWhenServerDown1079574862/002/a25942026/11/09 12:16:44 INFO Uploading batch count=125952026/11/09 12:16:44 ERROR Upload failed error="upload failed" count=125962026/11/09 12:16:44 ERROR Drain finished with paths left in queue remaining=12597--- PASS: TestQueueDeduplication (0.01s)2598--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)25992026/11/09 12:16:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestDrainGivesUpWhenServerDown1079574862/002/b2600--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)26012026/11/09 12:16:44 INFO Uploading batch count=226022026/11/09 12:16:44 ERROR Upload failed error="upload failed" count=226032026/11/09 12:16:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestDrainGivesUpWhenServerDown1079574862/002/c26042026/11/09 12:16:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestDrainGivesUpWhenServerDown1079574862/002/d2605--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)26062026/11/09 12:16:44 INFO Uploading batch count=226072026/11/09 12:16:44 ERROR Upload failed error="upload failed" count=226082026/11/09 12:16:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestDrainGivesUpWhenServerDown1079574862/002/e26092026/11/09 12:16:44 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestDrainGivesUpWhenServerDown1079574862/002/f26102026/11/09 12:16:44 ERROR Drain finished with paths left in queue remaining=1026112026/11/09 12:16:44 ERROR Accept failed error="too many open files"2612--- PASS: TestDrainIsolatesPoisonPath (0.02s)2613--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2614--- PASS: TestWorkerPrunesClosureDeps (0.03s)2615--- PASS: TestWorkerSkipsGCdPaths (0.04s)2616--- PASS: TestWorkerUploadsAndRemoves (0.04s)26172026/11/09 12:16:44 ERROR Accept failed error="too many open files"2618--- PASS: TestQueueConcurrentWriters (0.05s)2619--- PASS: TestQueueRemoveLargeClosure (0.05s)26202026/11/09 12:16:44 ERROR Accept failed error="too many open files"26212026/11/09 12:16:44 ERROR Accept failed error="too many open files"26222026/11/09 12:16:44 ERROR Failed to decode request error="read unix /private/var/tb/1/scratch/7464b49615ad7d9a/build/hook3183608694/test.sock->: i/o timeout"26232026/11/09 12:16:44 ERROR Failed to write response error="write unix /private/var/tb/1/scratch/7464b49615ad7d9a/build/hook3183608694/test.sock->: i/o timeout"2624--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26252026/11/09 12:16:44 ERROR Upload failed error="context deadline exceeded" count=226262026/11/09 12:16:44 ERROR Drain finished with paths left in queue remaining=42627--- PASS: TestDrainTimeout (0.22s)26282026/11/09 12:16:44 ERROR Accept failed error="too many open files"26292026/11/09 12:16:45 ERROR Accept failed error="too many open files"2630--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26312026/11/09 12:16:45 INFO Uploading batch count=126322026/11/09 12:16:45 INFO Uploading batch count=126332026/11/09 12:16:45 INFO Uploading batch count=126342026/11/09 12:16:45 ERROR Upload failed error="upload failed" count=126352026/11/09 12:16:45 INFO Uploading batch count=126362026/11/09 12:16:45 ERROR Upload failed error="upload failed" count=126372026/11/09 12:16:45 INFO Uploading batch count=126382026/11/09 12:16:45 ERROR Upload failed error="upload failed" count=126392026/11/09 12:16:45 INFO Uploading batch count=126402026/11/09 12:16:45 ERROR Upload failed error="upload failed" count=126412026/11/09 12:16:45 ERROR Drain finished with paths left in queue remaining=12642--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2643PASS2644Running signing tests...2645=== RUN TestExternalSigner2646=== PAUSE TestExternalSigner2647=== RUN TestExternalSignerWrongPublicKey2648=== PAUSE TestExternalSignerWrongPublicKey2649=== RUN TestExternalSignerErrors2650=== PAUSE TestExternalSignerErrors2651=== RUN TestExternalSignerRestartsAfterCrash2652=== PAUSE TestExternalSignerRestartsAfterCrash2653=== RUN TestExternalSignerProgramErrorKeepsProcess2654=== PAUSE TestExternalSignerProgramErrorKeepsProcess2655=== RUN TestExternalSignerClose2656=== PAUSE TestExternalSignerClose2657=== RUN TestExternalSignerRejectsInvalidPublicKey2658=== PAUSE TestExternalSignerRejectsInvalidPublicKey2659=== RUN TestExternalSignerCancellation2660=== PAUSE TestExternalSignerCancellation2661=== RUN TestGenerateFingerprint2662=== PAUSE TestGenerateFingerprint2663=== RUN TestParseSigningKey2664=== PAUSE TestParseSigningKey2665=== RUN TestSign2666=== PAUSE TestSign2667=== RUN TestSignBatch2668=== PAUSE TestSignBatch2669=== RUN TestNilKeyPublicKey2670=== PAUSE TestNilKeyPublicKey2671=== RUN TestSignErrors2672=== PAUSE TestSignErrors2673=== CONT TestExternalSigner2674=== CONT TestExternalSignerProgramErrorKeepsProcess2675=== CONT TestExternalSignerCancellation2676=== CONT TestSignErrors2677=== CONT TestNilKeyPublicKey2678--- PASS: TestNilKeyPublicKey (0.00s)2679=== CONT TestSignBatch2680=== CONT TestSign2681=== CONT TestParseSigningKey2682=== RUN TestParseSigningKey/valid_32-byte_key2683=== PAUSE TestParseSigningKey/valid_32-byte_key2684=== CONT TestGenerateFingerprint2685=== CONT TestExternalSignerErrors2686=== CONT TestExternalSignerRestartsAfterCrash2687=== CONT TestExternalSignerWrongPublicKey2688=== CONT TestExternalSignerRejectsInvalidPublicKey2689=== CONT TestExternalSignerClose2690=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2691=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2692=== RUN TestParseSigningKey/no_colon2693=== PAUSE TestParseSigningKey/no_colon2694=== RUN TestParseSigningKey/empty_name2695=== PAUSE TestParseSigningKey/empty_name2696=== RUN TestParseSigningKey/invalid_base642697=== PAUSE TestParseSigningKey/invalid_base642698=== RUN TestParseSigningKey/wrong_length2699=== PAUSE TestParseSigningKey/wrong_length2700=== CONT TestParseSigningKey/valid_32-byte_key2701=== CONT TestParseSigningKey/wrong_length2702=== CONT TestParseSigningKey/invalid_base642703=== CONT TestParseSigningKey/empty_name2704=== CONT TestParseSigningKey/no_colon2705=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2706=== RUN TestExternalSignerRejectsInvalidPublicKey/#002707=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002708=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2709=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2710=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2711=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2712=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2713=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2714=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2715=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2716=== CONT TestExternalSignerRejectsInvalidPublicKey/#002717=== RUN TestExternalSignerErrors/wrong_signature_name2718=== PAUSE TestExternalSignerErrors/wrong_signature_name2719=== RUN TestExternalSignerErrors/wrong_signature_length2720=== PAUSE TestExternalSignerErrors/wrong_signature_length2721=== RUN TestExternalSignerErrors/null_signatures2722=== PAUSE TestExternalSignerErrors/null_signatures2723=== RUN TestExternalSignerErrors/invalid_signature_base642724=== PAUSE TestExternalSignerErrors/invalid_signature_base642725=== RUN TestExternalSignerErrors/program_error2726=== PAUSE TestExternalSignerErrors/program_error2727=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2728=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2729=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2730=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2731--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2732 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2733 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2734 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2735 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2736 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2737=== RUN TestExternalSignerErrors/too_few_signatures2738=== PAUSE TestExternalSignerErrors/too_few_signatures2739=== RUN TestExternalSignerErrors/exit_on_request2740=== PAUSE TestExternalSignerErrors/exit_on_request2741=== RUN TestExternalSignerErrors/invalid_JSON2742=== RUN TestGenerateFingerprint/basic_with_references2743=== PAUSE TestGenerateFingerprint/basic_with_references2744=== RUN TestGenerateFingerprint/no_references2745=== PAUSE TestExternalSignerErrors/invalid_JSON2746=== RUN TestExternalSignerErrors/wrong_shape2747=== PAUSE TestExternalSignerErrors/wrong_shape2748=== RUN TestExternalSignerErrors/wrong_id2749=== PAUSE TestGenerateFingerprint/no_references2750=== PAUSE TestExternalSignerErrors/wrong_id2751=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2752=== RUN TestExternalSignerErrors/wrong_signatures_shape2753=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2754=== RUN TestSignErrors/nil_key2755=== PAUSE TestSignErrors/nil_key2756=== RUN TestSignErrors/nil_narinfo2757=== PAUSE TestSignErrors/nil_narinfo2758=== RUN TestSignErrors/invalid_narinfo2759=== PAUSE TestSignErrors/invalid_narinfo2760=== RUN TestSignErrors/canceled2761=== PAUSE TestSignErrors/canceled2762=== CONT TestSignErrors/nil_key2763--- PASS: TestSign (0.00s)2764=== RUN TestExternalSignerErrors/missing_signature_name2765=== PAUSE TestExternalSignerErrors/missing_signature_name2766=== RUN TestExternalSignerErrors/exit_at_startup2767=== PAUSE TestExternalSignerErrors/exit_at_startup2768=== RUN TestExternalSignerErrors/null2769=== PAUSE TestExternalSignerErrors/null2770=== RUN TestExternalSignerErrors/missing_signatures2771=== PAUSE TestExternalSignerErrors/missing_signatures2772=== RUN TestExternalSignerErrors/unrequested_key2773=== PAUSE TestExternalSignerErrors/unrequested_key2774--- PASS: TestParseSigningKey (0.00s)2775 --- PASS: TestParseSigningKey/wrong_length (0.00s)2776 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2777 --- PASS: TestParseSigningKey/empty_name (0.00s)2778 --- PASS: TestParseSigningKey/no_colon (0.00s)2779 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2780 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2781=== CONT TestExternalSignerErrors/wrong_signature_name2782=== CONT TestSignErrors/canceled2783=== CONT TestExternalSignerErrors/program_error2784=== CONT TestSignErrors/invalid_narinfo2785=== CONT TestExternalSignerErrors/null_signatures2786=== CONT TestSignErrors/nil_narinfo2787--- PASS: TestSignErrors (0.00s)2788 --- PASS: TestSignErrors/nil_key (0.00s)2789 --- PASS: TestSignErrors/canceled (0.00s)2790 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2791 --- PASS: TestSignErrors/nil_narinfo (0.00s)2792=== CONT TestExternalSignerErrors/unrequested_key2793=== CONT TestExternalSignerErrors/wrong_signature_length2794=== CONT TestExternalSignerErrors/missing_signatures2795--- PASS: TestSignBatch (0.00s)2796=== CONT TestExternalSignerErrors/null2797=== CONT TestExternalSignerErrors/exit_at_startup2798=== CONT TestExternalSignerErrors/missing_signature_name2799=== CONT TestExternalSignerErrors/wrong_signatures_shape2800=== CONT TestExternalSignerErrors/wrong_id2801=== CONT TestExternalSignerErrors/wrong_shape2802=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2803=== CONT TestExternalSignerErrors/invalid_JSON2804=== CONT TestExternalSignerErrors/exit_on_request2805=== CONT TestExternalSignerErrors/invalid_signature_base642806=== CONT TestExternalSignerErrors/too_few_signatures2807=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2808=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2809=== RUN TestGenerateFingerprint/invalid_nar_hash_length2810=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2811=== RUN TestGenerateFingerprint/invalid_store_path_prefix2812=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2813=== RUN TestGenerateFingerprint/invalid_reference_prefix2814=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2815=== CONT TestGenerateFingerprint/basic_with_references2816=== CONT TestGenerateFingerprint/invalid_nar_hash_length2817=== CONT TestGenerateFingerprint/invalid_store_path_prefix2818=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2819=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2820=== CONT TestGenerateFingerprint/no_references2821=== CONT TestGenerateFingerprint/invalid_reference_prefix2822--- PASS: TestGenerateFingerprint (0.00s)2823 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2824 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2825 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2826 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2827 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2828 --- PASS: TestGenerateFingerprint/no_references (0.00s)2829 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2830--- PASS: TestExternalSignerCancellation (0.14s)2831--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.21s)2832--- PASS: TestExternalSigner (0.32s)2833--- PASS: TestExternalSignerClose (0.84s)2834--- PASS: TestExternalSignerWrongPublicKey (0.93s)2835--- PASS: TestExternalSignerRestartsAfterCrash (1.63s)2836/private/var/tb/1/scratch/7464b49615ad7d9a/build/TestExternalSignerRestartsAfterCrash809655060/001/sign program: line 7: /private/var/tb/1/scratch/7464b49615ad7d9a/build/TestExternalSignerRestartsAfterCrash809655060/001/sign program.starts: No such file or directory2837--- PASS: TestExternalSignerErrors (0.00s)2838 --- PASS: TestExternalSignerErrors/missing_signature_name (0.38s)2839 --- PASS: TestExternalSignerErrors/null (0.47s)2840 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.57s)2841 --- PASS: TestExternalSignerErrors/wrong_id (0.66s)2842 --- PASS: TestExternalSignerErrors/wrong_signature_length (0.76s)2843 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.05s)2844 --- PASS: TestExternalSignerErrors/exit_on_request (1.13s)2845 --- PASS: TestExternalSignerErrors/program_error (1.23s)2846 --- PASS: TestExternalSignerErrors/null_signatures (1.32s)2847 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.41s)2848 --- PASS: TestExternalSignerErrors/too_few_signatures (1.51s)2849 --- PASS: TestExternalSignerErrors/unrequested_key (1.68s)2850 --- PASS: TestExternalSignerErrors/exit_at_startup (1.77s)2851 --- PASS: TestExternalSignerErrors/wrong_shape (1.85s)2852 --- PASS: TestExternalSignerErrors/missing_signatures (1.94s)2853 --- PASS: TestExternalSignerErrors/invalid_JSON (2.04s)2854PASS2855Running OpenBao signer tests...2856=== RUN TestSign2857=== PAUSE TestSign2858=== RUN TestSignErrors2859=== PAUSE TestSignErrors2860=== RUN TestServe2861=== PAUSE TestServe2862=== RUN TestServeRejectsGarbage2863=== PAUSE TestServeRejectsGarbage2864=== CONT TestSign2865=== CONT TestServeRejectsGarbage2866=== CONT TestServe2867--- PASS: TestServeRejectsGarbage (0.00s)2868=== CONT TestSignErrors2869=== RUN TestSignErrors/invalid_base642870=== PAUSE TestSignErrors/invalid_base642871=== RUN TestSignErrors/http_error2872=== PAUSE TestSignErrors/http_error2873=== RUN TestSignErrors/invalid_json2874=== PAUSE TestSignErrors/invalid_json2875=== RUN TestSignErrors/no_prefix2876=== PAUSE TestSignErrors/no_prefix2877=== CONT TestSignErrors/invalid_base642878=== CONT TestSignErrors/invalid_json2879=== CONT TestSignErrors/no_prefix2880=== CONT TestSignErrors/http_error2881--- PASS: TestServe (0.00s)2882--- PASS: TestSign (0.00s)2883--- PASS: TestSignErrors (0.00s)2884 --- PASS: TestSignErrors/invalid_json (0.00s)2885 --- PASS: TestSignErrors/http_error (0.00s)2886 --- PASS: TestSignErrors/invalid_base64 (0.00s)2887 --- PASS: TestSignErrors/no_prefix (0.00s)2888PASS