niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #485
· 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.06s)25=== RUN TestDumpPathCaseHackCollision26--- PASS: TestDumpPathCaseHackCollision (0.00s)27=== RUN TestDumpPathMatchesNix28=== PAUSE TestDumpPathMatchesNix29=== RUN TestDumpPathSingleFile30=== PAUSE TestDumpPathSingleFile31=== RUN TestDumpPathWriterError32=== PAUSE TestDumpPathWriterError33=== RUN TestEncodeNixBase3234=== PAUSE TestEncodeNixBase3235=== RUN TestEncodeNixBase32WithRealHash36=== PAUSE TestEncodeNixBase32WithRealHash37=== RUN TestConvertHashToNix3238=== PAUSE TestConvertHashToNix3239=== RUN TestGetStorePathHash40=== PAUSE TestGetStorePathHash41=== RUN TestPathInfoHashCompatibility42=== PAUSE TestPathInfoHashCompatibility43=== RUN TestParsePathInfoJSON44=== PAUSE TestParsePathInfoJSON45=== RUN TestParsePathInfoJSONMultiplePaths46=== PAUSE TestParsePathInfoJSONMultiplePaths47=== RUN TestPathInfoCACompatibility48=== PAUSE TestPathInfoCACompatibility49=== RUN TestRateLimiterFeedback50=== PAUSE TestRateLimiterFeedback51=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess52=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess53=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer54=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer55=== RUN TestRegisterUploadedObject_OutlivesPush56=== PAUSE TestRegisterUploadedObject_OutlivesPush57=== RUN TestResolveStorePath58=== PAUSE TestResolveStorePath59=== RUN TestDoWithRetry_BodyReplayedViaGetBody60=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody61=== RUN TestRetryTimeoutOutlastsMaxRetries62=== PAUSE TestRetryTimeoutOutlastsMaxRetries63=== RUN TestDoWithRetry_FinalResponseBodyReadable64=== PAUSE TestDoWithRetry_FinalResponseBodyReadable65=== RUN TestShellSplit66=== PAUSE TestShellSplit67=== RUN TestShellSplitErrors68=== PAUSE TestShellSplitErrors69=== RUN TestStreamPushReportsEveryPath70=== PAUSE TestStreamPushReportsEveryPath71=== RUN TestStreamPushBatchesUnderLoad72=== PAUSE TestStreamPushBatchesUnderLoad73=== RUN TestStreamPushIsolatesFailures74=== PAUSE TestStreamPushIsolatesFailures75=== RUN TestStreamPushGivesUpOnDeadServer76=== PAUSE TestStreamPushGivesUpOnDeadServer77=== RUN TestStreamPushRequestLine78=== PAUSE TestStreamPushRequestLine79=== RUN TestStreamPushReportsSignatures80=== PAUSE TestStreamPushReportsSignatures81=== RUN TestStreamPushReportsSkippedPaths82=== PAUSE TestStreamPushReportsSkippedPaths83=== RUN TestClientSignaturesByStorePath84=== PAUSE TestClientSignaturesByStorePath85=== RUN TestStreamPushStopsWhenCanceled86=== PAUSE TestStreamPushStopsWhenCanceled87=== RUN TestSetClientTLS88=== PAUSE TestSetClientTLS89=== RUN TestSetClientTLSDoesNotMutateDefaultTransport90=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport91=== RUN TestSetClientTLSErrors92=== PAUSE TestSetClientTLSErrors93=== RUN TestStaticToken94=== PAUSE TestStaticToken95=== RUN TestFileTokenReadsAndCaches96=== PAUSE TestFileTokenReadsAndCaches97=== RUN TestFileTokenMissing98=== PAUSE TestFileTokenMissing99=== RUN TestFileTokenEmpty100=== PAUSE TestFileTokenEmpty101=== RUN TestScriptTokenNoExpiryRerunsEveryCall102=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall103=== RUN TestScriptTokenCachesUntilRefresh104=== PAUSE TestScriptTokenCachesUntilRefresh105=== RUN TestScriptTokenEmptyToken106=== PAUSE TestScriptTokenEmptyToken107=== RUN TestScriptTokenBadJSON108=== PAUSE TestScriptTokenBadJSON109=== RUN TestScriptTokenScriptFails110=== PAUSE TestScriptTokenScriptFails111=== RUN TestScriptTokenEmptyCommand112=== PAUSE TestScriptTokenEmptyCommand113=== CONT TestDoServerRequestAttachesToken114=== CONT TestRetryTimeoutOutlastsMaxRetries115=== CONT TestClientSignaturesByStorePath116--- PASS: TestClientSignaturesByStorePath (0.00s)117=== CONT TestRegisterUploadedObject_OutlivesPush118=== CONT TestSetClientTLS119=== CONT TestScriptTokenEmptyCommand120--- PASS: TestScriptTokenEmptyCommand (0.00s)121=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer122=== CONT TestScriptTokenScriptFails123=== CONT TestScriptTokenBadJSON124=== CONT TestScriptTokenEmptyToken125=== CONT TestScriptTokenCachesUntilRefresh126=== CONT TestScriptTokenNoExpiryRerunsEveryCall127=== CONT TestFileTokenEmpty128=== CONT TestFileTokenMissing129=== CONT TestFileTokenReadsAndCaches130=== CONT TestStaticToken131=== CONT TestSetClientTLSErrors132=== CONT TestSetClientTLSDoesNotMutateDefaultTransport133=== CONT TestStreamPushReportsSkippedPaths134=== CONT TestStreamPushStopsWhenCanceled135=== CONT TestStreamPushGivesUpOnDeadServer136=== CONT TestStreamPushReportsSignatures137=== CONT TestStreamPushRequestLine138=== CONT TestEncodeNixBase32WithRealHash139=== CONT TestDoWithRetry_BodyReplayedViaGetBody140=== CONT TestResolveStorePath1412026/11/11 22:53:13 ERROR Upload failed error=boom count=1142--- PASS: TestStreamPushReportsSignatures (0.00s)143=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess144--- PASS: TestStaticToken (0.00s)145=== CONT TestRateLimiterFeedback146--- PASS: TestEncodeNixBase32WithRealHash (0.00s)147=== CONT TestPathInfoCACompatibility148=== RUN TestPathInfoCACompatibility/null_ca_field149=== PAUSE TestPathInfoCACompatibility/null_ca_field150=== RUN TestPathInfoCACompatibility/old_string_format_-_text151=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text152=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive1532026/11/11 22:53:13 ERROR Upload failed error=boom count=1154--- PASS: TestFileTokenMissing (0.00s)155=== CONT TestParsePathInfoJSONMultiplePaths156=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths157=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths158=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths159=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths160=== CONT TestParsePathInfoJSON161=== RUN TestParsePathInfoJSON/Nix_format162=== PAUSE TestParsePathInfoJSON/Nix_format163=== RUN TestParsePathInfoJSON/Lix_format164=== PAUSE TestParsePathInfoJSON/Lix_format165=== RUN TestParsePathInfoJSON/empty_input166--- PASS: TestFileTokenEmpty (0.00s)167=== CONT TestPathInfoHashCompatibility168=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive169=== RUN TestPathInfoCACompatibility/new_structured_format_-_text170--- PASS: TestStreamPushStopsWhenCanceled (0.00s)171--- PASS: TestScriptTokenScriptFails (0.01s)172=== CONT TestConvertHashToNix32173=== CONT TestGetStorePathHash174--- PASS: TestFileTokenReadsAndCaches (0.00s)1752026/11/11 22:53:13 ERROR Upload failed error="connection refused" count=201762026/11/11 22:53:13 ERROR Server seems unavailable, giving up on batch untried=17177=== CONT TestUploadMultipart_PartsInParallel178=== RUN TestRateLimiterFeedback/429_enables_limiter179--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)180=== CONT TestEncodeNixBase32181=== RUN TestEncodeNixBase32/test_string_hash182=== RUN TestSetClientTLSErrors/missing_cert_file183--- PASS: TestResolveStorePath (0.00s)184=== CONT TestDumpPathWriterError185--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)186=== CONT TestDumpPathSingleFile187=== RUN TestSetClientTLS/rejects_connection_without_client_cert1882026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:55973189=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text190=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method191=== PAUSE TestEncodeNixBase32/test_string_hash192=== RUN TestEncodeNixBase32/empty_input193=== PAUSE TestSetClientTLSErrors/missing_cert_file194--- PASS: TestStreamPushReportsSkippedPaths (0.01s)195=== CONT TestDumpPathMatchesNix1962026/11/11 22:53:13 WARN Rate limiter enabled after throttle name=server-test rate=51972026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55984198=== PAUSE TestRateLimiterFeedback/429_enables_limiter1992026/11/11 22:53:13 WARN Rate limiter enabled after throttle name=server-test rate=5200=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method201=== PAUSE TestParsePathInfoJSON/empty_input202=== RUN TestRateLimiterFeedback/503_enables_limiter203=== PAUSE TestRateLimiterFeedback/503_enables_limiter204=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)205=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)206=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon207=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon208=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI209=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI210=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512211=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512212=== RUN TestConvertHashToNix32/SRI_format_to_Nix32213=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32214=== RUN TestConvertHashToNix32/already_Nix32_format215=== PAUSE TestConvertHashToNix32/already_Nix32_format216=== RUN TestConvertHashToNix32/invalid_format217=== PAUSE TestConvertHashToNix32/invalid_format218=== CONT TestStreamPushReportsEveryPath219=== RUN TestGetStorePathHash/valid_store_path220=== PAUSE TestGetStorePathHash/valid_store_path221=== RUN TestGetStorePathHash/basename_without_hyphen_should_error222=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error223=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error224=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error225=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error226=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error227=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert228=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA229=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA230=== RUN TestSetClientTLS/preserves_debug_logging_transport231=== PAUSE TestSetClientTLS/preserves_debug_logging_transport232=== CONT TestStreamPushBatchesUnderLoad233=== CONT TestStreamPushIsolatesFailures2342026/11/11 22:53:13 WARN Rate limiter backed off name=server-test rate=5235=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false236=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false237=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true238=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true239=== PAUSE TestEncodeNixBase32/empty_input240--- PASS: TestRegisterUploadedObject_OutlivesPush (0.01s)241--- PASS: TestStreamPushReportsEveryPath (0.00s)242--- PASS: TestDoServerRequestAttachesToken (0.01s)243=== CONT TestPartSizeForNAR244=== RUN TestPartSizeForNAR/zero_stays_at_minimum245=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum246=== RUN TestPartSizeForNAR/small_stays_at_minimum247=== PAUSE TestPartSizeForNAR/small_stays_at_minimum248=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum249=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum250=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts251=== CONT TestUploadMultipart_ReturnsAfterDroppedBody252=== RUN TestParsePathInfoJSON/whitespace_only2532026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:55984254=== PAUSE TestParsePathInfoJSON/whitespace_only255=== RUN TestParsePathInfoJSON/invalid_JSON256=== PAUSE TestParsePathInfoJSON/invalid_JSON257=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter2582026/11/11 22:53:13 ERROR Upload failed error="bad path" count=3259=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter260=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter261=== CONT TestDoWithRetry_FinalResponseBodyReadable262=== CONT TestRegisterUploadedObjectReusesConnections263=== CONT TestShellSplit264=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica265=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry266=== CONT TestShellSplitErrors267=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths268=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths269=== CONT TestPathInfoCACompatibility/new_structured_format_-_text270=== CONT TestPathInfoCACompatibility/null_ca_field271=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method272=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive273=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)274=== CONT TestConvertHashToNix32/SRI_format_to_Nix32275=== CONT TestGetStorePathHash/valid_store_path276=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512277=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI278=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon2792026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:55973280=== CONT TestFilterOversizedClosures281=== RUN TestFilterOversizedClosures/no_limit_keeps_everything282=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything283=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped284=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped285=== RUN TestFilterOversizedClosures/all_closures_skipped286=== PAUSE TestFilterOversizedClosures/all_closures_skipped287=== CONT TestPathInfoCACompatibility/old_string_format_-_text288=== CONT TestSetClientTLS/rejects_connection_without_client_cert289=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error290=== CONT TestConvertHashToNix32/already_Nix32_format291=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error292=== CONT TestGetStorePathHash/basename_without_hyphen_should_error293=== CONT TestConvertHashToNix32/invalid_format294=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun295=== CONT TestCaseHackSuffix296=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts297=== RUN TestPartSizeForNAR/1_TiB298=== PAUSE TestPartSizeForNAR/1_TiB299=== RUN TestPartSizeForNAR/5_TiB_S3_max_object300=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object301=== RUN TestPartSizeForNAR/capped_at_5_GiB302=== PAUSE TestPartSizeForNAR/capped_at_5_GiB303=== RUN TestSetClientTLSErrors/missing_key_file304=== PAUSE TestSetClientTLSErrors/missing_key_file305=== RUN TestSetClientTLSErrors/missing_ca_file306=== PAUSE TestSetClientTLSErrors/missing_ca_file307=== RUN TestSetClientTLSErrors/invalid_ca_file308=== PAUSE TestSetClientTLSErrors/invalid_ca_file309=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA310=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter311=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false312--- PASS: TestStreamPushIsolatesFailures (0.00s)313--- PASS: TestShellSplit (0.00s)314--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.01s)315--- PASS: TestShellSplitErrors (0.00s)316=== CONT TestSetClientTLS/preserves_debug_logging_transport317=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true318--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)319 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)320 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)321--- PASS: TestScriptTokenEmptyToken (0.01s)322--- PASS: TestScriptTokenBadJSON (0.01s)3232026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:559733242026/11/11 22:53:13 WARN Rate limiter enabled after throttle name=server-test rate=5325=== CONT TestEncodeNixBase32/test_string_hash326=== CONT TestParsePathInfoJSON/invalid_JSON327=== CONT TestParsePathInfoJSON/Lix_format3282026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:56003329=== CONT TestEncodeNixBase32/empty_input330=== CONT TestParsePathInfoJSON/empty_input331=== CONT TestFilterOversizedClosures/no_limit_keeps_everything332=== CONT TestFilterOversizedClosures/all_closures_skipped3332026/11/11 22:53:13 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=50334--- PASS: TestGetStorePathHash (0.00s)335 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)336 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)337 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)338 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)339=== CONT TestParsePathInfoJSON/Nix_format340--- PASS: TestStreamPushBatchesUnderLoad (0.00s)341 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)342 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)343=== CONT TestParsePathInfoJSON/whitespace_only344=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3452026/11/11 22:53:13 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=2000346=== CONT TestPartSizeForNAR/small_stays_at_minimum347=== CONT TestPartSizeForNAR/capped_at_5_GiB348=== CONT TestSetClientTLSErrors/missing_cert_file349=== CONT TestPartSizeForNAR/1_TiB350=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts351=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum352=== CONT TestSetClientTLSErrors/invalid_ca_file353=== CONT TestPartSizeForNAR/zero_stays_at_minimum354=== CONT TestRateLimiterFeedback/429_enables_limiter355--- PASS: TestPathInfoHashCompatibility (0.00s)356 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)357 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)358 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)359 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)360=== CONT TestPartSizeForNAR/5_TiB_S3_max_object361=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter362--- PASS: TestEncodeNixBase32 (0.00s)363 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)364 --- PASS: TestEncodeNixBase32/empty_input (0.00s)365--- PASS: TestFilterOversizedClosures (0.00s)366 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)367 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)368 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)369--- PASS: TestConvertHashToNix32 (0.00s)370 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)371 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)372 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)373--- PASS: TestPathInfoCACompatibility (0.01s)374 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)375 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)376 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)377 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)378 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)379=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter380--- PASS: TestPartSizeForNAR (0.00s)381 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)382 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)383 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)384 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)385 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)386 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)387 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)3882026/11/11 22:53:13 INFO Garbage collection started3892026/11/11 22:53:13 WARN Rate limiter backed off name=server-test rate=53902026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:559733912026/11/11 22:53:13 INFO Garbage collection started3922026/11/11 22:53:13 WARN Rate limiter enabled after throttle name=s3-test rate=5393--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)394=== CONT TestSetClientTLSErrors/missing_ca_file395=== CONT TestSetClientTLSErrors/missing_key_file396=== CONT TestRateLimiterFeedback/503_enables_limiter3972026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55995398--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.01s)3992026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:55973400--- PASS: TestSetClientTLSErrors (0.01s)401 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)402 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)403 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)404 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)4052026/11/11 22:53:13 WARN Rate limiter enabled after throttle name=server-test rate=54062026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:56062407--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.01s)408--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)4092026/11/11 22:53:13 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=0410--- PASS: TestParsePathInfoJSON (0.01s)411 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)412 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)413 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)414 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)415 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)4162026/11/11 22:53:13 WARN Rate limiter enabled after throttle name=server-test rate=54172026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:56076418--- PASS: TestStreamPushRequestLine (0.02s)4192026/11/11 22:53:13 WARN Rate limiter backed off name=server-test rate=54202026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:559734212026/11/11 22:53:13 WARN Rate limiter backed off name=server-test rate=5422--- PASS: TestRateLimiterFeedback (0.01s)423 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)424 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)425 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)426 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)4272026/11/11 22:53:13 WARN Garbage collection finished on another replica. Its statistics are not available here428--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)4292026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:559734302026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:559734312026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:559734322026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:559734332026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:559734342026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:559734352026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:559734362026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:559734372026/11/11 22:53:13 http: TLS handshake error from 127.0.0.1:56000: remote error: tls: bad certificate4382026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:55973439--- PASS: TestSetClientTLS (0.01s)440 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)441 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)442 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)4432026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:55973444--- PASS: TestRegisterUploadedObjectReusesConnections (0.03s)4452026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:559734462026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:559734472026/11/11 22:53:13 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:55973448--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.05s)449--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)450--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)451--- PASS: TestDumpPathWriterError (0.05s)452--- PASS: TestDumpPathSingleFile (0.05s)453--- PASS: TestCaseHackSuffix (0.05s)454--- PASS: TestDumpPathMatchesNix (0.08s)4552026/11/11 22:53:13 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55974/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55974/api/uploads/complete4562026/11/11 22:53:13 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55974/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55974/api/uploads/complete4572026/11/11 22:53:13 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4582026/11/11 22:53:13 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4592026/11/11 22:53:13 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55974/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55974/api/uploads/complete4602026/11/11 22:53:13 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"461--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (0.10s)462--- PASS: TestUploadMultipart_PartsInParallel (0.62s)463--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.01s)464PASS465Running server tests...466The files belonging to this database system will be owned by user "_tribuchetbld5".467This user must also own the server process.468469The database cluster will be initialized with locale "C".470The default database encoding has accordingly been set to "SQL_ASCII".471The default text search configuration will be set to "english".472473Data page checksums are enabled.474475creating directory /private/var/tb/5/scratch/2ea555b3b60ac49d/build/postgres2697273197/data ... ok476creating subdirectories ... ok477selecting dynamic shared memory implementation ... posix478selecting default "max_connections" ... 100479selecting default "shared_buffers" ... 128MB480selecting default time zone ... UTC481creating configuration files ... ok482running bootstrap script ... ok483performing post-bootstrap initialization ... ok484syncing data to disk ... ok485486initdb: warning: enabling "trust" authentication for local connections487initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.488489Success. You can now start the database server using:490491 pg_ctl -D /private/var/tb/5/scratch/2ea555b3b60ac49d/build/postgres2697273197/data -l logfile start492493/private/var/tb/5/scratch/2ea555b3b60ac49d/build/postgres2697273197:5432 - no response4942026-11-11 22:53:15.689 UTC [69122] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit4952026-11-11 22:53:15.689 UTC [69122] LOG: listening on Unix socket "/private/var/tb/5/scratch/2ea555b3b60ac49d/build/postgres2697273197/.s.PGSQL.5432"4962026-11-11 22:53:15.691 UTC [69129] LOG: database system was shut down at 2026-11-11 22:53:15 UTC4972026-11-11 22:53:15.692 UTC [69122] LOG: database system is ready to accept connections498/private/var/tb/5/scratch/2ea555b3b60ac49d/build/postgres2697273197:5432 - accepting connections499{"timestamp":"2026-11-11T22:53:15.909189Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"a01aafe5-4fbc-4f87-ae8e-d750613e1d66","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)"}500=== RUN TestAbortSucceeded501=== PAUSE TestAbortSucceeded502=== RUN TestService_AuthMiddleware503=== PAUSE TestService_AuthMiddleware504=== RUN TestService_AuthMiddleware_MTLSProxyHeader505=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader506=== RUN TestService_AuthMiddleware_MTLSBoundSubjects507=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects508=== RUN TestService_ReadAuthMiddleware509=== PAUSE TestService_ReadAuthMiddleware510=== RUN TestService_AuthMiddleware_OIDC511=== PAUSE TestService_AuthMiddleware_OIDC512=== RUN TestService_RequireScope_OIDC513=== PAUSE TestService_RequireScope_OIDC514=== RUN TestService_ReadScope_PublicByDefault515=== PAUSE TestService_ReadScope_PublicByDefault516=== RUN TestCacheConfigHandler517=== PAUSE TestCacheConfigHandler518=== RUN TestCacheStatsHandler519=== PAUSE TestCacheStatsHandler520=== RUN TestClientCADerivations521=== PAUSE TestClientCADerivations522=== RUN TestClientErrorHandling523=== PAUSE TestClientErrorHandling524=== RUN TestClientIntegration525=== PAUSE TestClientIntegration526=== RUN TestClientMultipleUploads527=== PAUSE TestClientMultipleUploads528=== RUN TestClientWithDependencies529=== PAUSE TestClientWithDependencies530=== RUN TestClientSharedPathCommittedMidPush531=== PAUSE TestClientSharedPathCommittedMidPush532=== RUN TestPinProtectsFromGC533=== PAUSE TestPinProtectsFromGC534=== RUN TestClientPushesUseOnePush535=== PAUSE TestClientPushesUseOnePush536=== RUN TestClientFallsBackToClosures537=== PAUSE TestClientFallsBackToClosures538=== RUN TestDeleteClosuresRacingPins539=== PAUSE TestDeleteClosuresRacingPins540=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock541=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock542=== RUN TestResolveDBConnectionString543=== PAUSE TestResolveDBConnectionString544=== RUN TestConnectWaitsForAPeerMigration545=== PAUSE TestConnectWaitsForAPeerMigration546=== RUN TestLeadElectsOneAndHandsOver547=== PAUSE TestLeadElectsOneAndHandsOver548=== RUN TestLeadIncumbentWinsAfterRestart5492026/11/11 22:53:16 INFO lead: acquired remote=192.0.2.1:1234 generation=15502026/11/11 22:53:16 INFO lead: released remote=192.0.2.1:1234 generation=15512026/11/11 22:53:16 INFO lead: acquired remote=192.0.2.1:1234 generation=25522026/11/11 22:53:17 INFO lead: released remote=192.0.2.1:1234 generation=2553--- PASS: TestLeadIncumbentWinsAfterRestart (1.88s)554=== RUN TestLeadUnannouncedStandbyYieldsToIncumbent555=== PAUSE TestLeadUnannouncedStandbyYieldsToIncumbent556=== RUN TestLeadIncumbentAnnouncesAtOnce557=== PAUSE TestLeadIncumbentAnnouncesAtOnce558=== RUN TestLeadGenerationGrowsWithEveryGrant559=== PAUSE TestLeadGenerationGrowsWithEveryGrant560=== RUN TestLeadEndsOnShutdown561=== PAUSE TestLeadEndsOnShutdown562=== RUN TestLeadEndsWhenItsConnectionHangs5632026/11/11 22:53:18 INFO lead: acquired remote=192.0.2.1:1234 generation=15642026-11-11 22:53:19.468 UTC [69165] FATAL: terminating connection due to administrator command5652026/11/11 22:53:19 INFO lead: acquired remote=192.0.2.1:1234 generation=25662026/11/11 22:53:20 WARN lead: lock connection lost error="timeout: context deadline exceeded"5672026/11/11 22:53:20 INFO lead: released remote=192.0.2.1:1234 generation=15682026/11/11 22:53:20 INFO lead: released remote=192.0.2.1:1234 generation=2569--- PASS: TestLeadEndsWhenItsConnectionHangs (2.98s)570=== RUN TestGCAdvisoryLockBlocksConcurrentRun571=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun572=== RUN TestGCBugBareHashReferences573=== PAUSE TestGCBugBareHashReferences574=== RUN TestGCMetrics575=== PAUSE TestGCMetrics576=== RUN TestPushDedupSurvivesConcurrentGC577=== PAUSE TestPushDedupSurvivesConcurrentGC578=== RUN TestDeduplicatedObjectsRecordedAsPending579=== PAUSE TestDeduplicatedObjectsRecordedAsPending580=== RUN TestGCSweepSkipsPendingObjects581=== PAUSE TestGCSweepSkipsPendingObjects582=== RUN TestTombstonedObjectOfferedWithoutWaiting583=== PAUSE TestTombstonedObjectOfferedWithoutWaiting584=== RUN TestGCSweepDeliversEachKeyOnce585=== PAUSE TestGCSweepDeliversEachKeyOnce586=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection587=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection588=== RUN TestForceGCDuringPushOffersSweptObject589=== PAUSE TestForceGCDuringPushOffersSweptObject590=== RUN TestFailedS3DeleteKeepsTombstone591=== PAUSE TestFailedS3DeleteKeepsTombstone592=== RUN TestSweepSkipsRowsLockedByPush593=== PAUSE TestSweepSkipsRowsLockedByPush594=== RUN TestRegisterCompletedObjectNeedsPendingRow595=== PAUSE TestRegisterCompletedObjectNeedsPendingRow596=== RUN TestGetExistingObjectsLocksRows597=== PAUSE TestGetExistingObjectsLocksRows598=== RUN TestSweepRechecksPendingAfterLocking599=== PAUSE TestSweepRechecksPendingAfterLocking600=== RUN TestPushWaitsForSweepHoldingRow601=== PAUSE TestPushWaitsForSweepHoldingRow602=== RUN TestCommitRacingPendingCleanupKeepsObjects603=== PAUSE TestCommitRacingPendingCleanupKeepsObjects604=== RUN TestGCEndsOnShutdown605=== PAUSE TestGCEndsOnShutdown606=== RUN TestGCTaskStore_StartNew607=== PAUSE TestGCTaskStore_StartNew608=== RUN TestGCTaskStore_DeduplicateSameParams609=== PAUSE TestGCTaskStore_DeduplicateSameParams610=== RUN TestGCTaskStore_ConflictDifferentParams611=== PAUSE TestGCTaskStore_ConflictDifferentParams612=== RUN TestGCTaskStore_GetEmpty613=== PAUSE TestGCTaskStore_GetEmpty614=== RUN TestGCTaskStore_GetReturnsLatest615=== PAUSE TestGCTaskStore_GetReturnsLatest616=== RUN TestGCTaskStore_CompletedAllowsNewTask617=== PAUSE TestGCTaskStore_CompletedAllowsNewTask618=== RUN TestGCTaskStore_PhaseUpdates619=== PAUSE TestGCTaskStore_PhaseUpdates620=== RUN TestGCTaskStore_Fail621=== PAUSE TestGCTaskStore_Fail622=== RUN TestGracefulShutdownDrainsInflight623=== PAUSE TestGracefulShutdownDrainsInflight624=== RUN TestService_healthCheckHandler625=== PAUSE TestService_healthCheckHandler626=== RUN TestService_readinessHandler627=== PAUSE TestService_readinessHandler628=== RUN TestGenerateLandingPage629=== PAUSE TestGenerateLandingPage630=== RUN TestEnsureAbortUploadsRule631=== PAUSE TestEnsureAbortUploadsRule632=== RUN TestCacheConfigHandlerMaxNarSize633=== PAUSE TestCacheConfigHandlerMaxNarSize634=== RUN TestCreatePendingClosureRejectsOversizedNAR635=== PAUSE TestCreatePendingClosureRejectsOversizedNAR636=== RUN TestNARDeduplicationMetadataUploadBug637=== PAUSE TestNARDeduplicationMetadataUploadBug638=== RUN TestMetricsInventory639=== PAUSE TestMetricsInventory640=== RUN TestMetricsCommit641=== PAUSE TestMetricsCommit642=== RUN TestService_NativeMTLS643=== PAUSE TestService_NativeMTLS644=== RUN TestServerTLSConfig645=== PAUSE TestServerTLSConfig646=== RUN TestMultipartCleanup647=== PAUSE TestMultipartCleanup648=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded649=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded650=== RUN TestPendingCleanupUsesOneCutoff651=== PAUSE TestPendingCleanupUsesOneCutoff652=== RUN TestObjectStatsTrigger653=== PAUSE TestObjectStatsTrigger654=== RUN TestObjectStatsUpdatedOncePerCommit655=== PAUSE TestObjectStatsUpdatedOncePerCommit656=== RUN TestOrphanedObjectsGC657=== PAUSE TestOrphanedObjectsGC658=== RUN TestOrphanedObjectsGCStressTest659=== PAUSE TestOrphanedObjectsGCStressTest660=== RUN TestCreatePin_ReservedPins661=== PAUSE TestCreatePin_ReservedPins662=== RUN TestPresentReportsOnlyClosureRoots663=== PAUSE TestPresentReportsOnlyClosureRoots664=== RUN TestPresentRefreshesOnlyStaleClosures665=== PAUSE TestPresentRefreshesOnlyStaleClosures666=== RUN TestPresentNotReportedWhileGCDeletesClosure667=== PAUSE TestPresentNotReportedWhileGCDeletesClosure668=== RUN TestParseSingleRange669=== PAUSE TestParseSingleRange670=== RUN TestProxyHeadersOnlyTrustedOnSocket6712026/11/11 22:53:21 INFO Starting HTTP server address=127.0.0.1:560956722026/11/11 22:53:21 INFO Starting HTTP server address=proxy.sock6732026/11/11 22:53:21 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6742026/11/11 22:53:21 INFO Shutdown signal received, draining in-flight requests timeout=10s675--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)676=== RUN TestIsValidCachePath677=== PAUSE TestIsValidCachePath678=== RUN TestReadProxyNarinfo679=== PAUSE TestReadProxyNarinfo680=== RUN TestReadProxyNarinfoAlreadyDecompressed681=== PAUSE TestReadProxyNarinfoAlreadyDecompressed682=== RUN TestReadProxyContentNegotiation683=== PAUSE TestReadProxyContentNegotiation684=== RUN TestReadProxyNarStreaming685=== PAUSE TestReadProxyNarStreaming686=== RUN TestReadProxy404687=== PAUSE TestReadProxy404688=== RUN TestReadProxyInvalidPath689=== PAUSE TestReadProxyInvalidPath690=== RUN TestReadProxyHead691=== PAUSE TestReadProxyHead692=== RUN TestReadProxyOutlastsServerWriteTimeout693=== PAUSE TestReadProxyOutlastsServerWriteTimeout694=== RUN TestReadProxyConditionalGet695=== PAUSE TestReadProxyConditionalGet696=== RUN TestReadProxyRootRedirectsToIndexHTML697=== PAUSE TestReadProxyRootRedirectsToIndexHTML698=== RUN TestReadProxyDisabled699=== PAUSE TestReadProxyDisabled700=== RUN TestReadRedirectNar701=== PAUSE TestReadRedirectNar702=== RUN TestReadRedirectKeepsNarinfoProxied703=== PAUSE TestReadRedirectKeepsNarinfoProxied704=== RUN TestReadProxyRangeRequest705=== PAUSE TestReadProxyRangeRequest706=== RUN TestReadRedirectUsesPublicS3URL707=== PAUSE TestReadRedirectUsesPublicS3URL708=== RUN TestPush_OverlappingRootsStoreOneRowPerKey709=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey710=== RUN TestPush_CompleteCommitsEveryRoot711=== PAUSE TestPush_CompleteCommitsEveryRoot712=== RUN TestPush_RepeatedRootCommitsOnce713=== PAUSE TestPush_RepeatedRootCommitsOnce714=== RUN TestPush_CompleteWaitsForCleanupOfThePush715=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush716=== RUN TestPush_RootsAreLockedInByteOrder717=== PAUSE TestPush_RootsAreLockedInByteOrder718=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit719=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit720=== RUN TestPush_RejectsBadRequests721=== PAUSE TestPush_RejectsBadRequests722=== RUN TestPush_SignsNarinfosOfItsPendingObjects723=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects724=== RUN TestSharedNarBothUploadsComplete725=== PAUSE TestSharedNarBothUploadsComplete726=== RUN TestCompleteMultipartUpload_ErrorButObjectExists727=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists728=== RUN TestCompletedNarNotReofferedAcrossClosures729=== PAUSE TestCompletedNarNotReofferedAcrossClosures730=== RUN TestPresignedUploadRegisteredBeforeCommit731=== PAUSE TestPresignedUploadRegisteredBeforeCommit732=== RUN TestService_Rustfstest733=== PAUSE TestService_Rustfstest734=== RUN TestParseSize735=== PAUSE TestParseSize736=== RUN TestSkippedUploadsHandler737=== PAUSE TestSkippedUploadsHandler738=== RUN TestSystemdListenerNotActivated739--- PASS: TestSystemdListenerNotActivated (0.00s)740=== RUN TestWatchdogBeatsWhenHealthy741--- PASS: TestWatchdogBeatsWhenHealthy (0.02s)742=== RUN TestWatchdogSkipsWhenUnhealthy7432026/11/11 22:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7442026/11/11 22:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7452026/11/11 22:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7462026/11/11 22:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7472026/11/11 22:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7482026/11/11 22:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7492026/11/11 22:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7502026/11/11 22:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7512026/11/11 22:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7522026/11/11 22:53:21 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"753--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)754=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle755=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle756=== RUN TestProxyWriteTimeout757=== PAUSE TestProxyWriteTimeout758=== RUN TestPendingClosureWriteTimeout759=== PAUSE TestPendingClosureWriteTimeout760=== RUN TestIsValidUploadKey761=== PAUSE TestIsValidUploadKey762=== RUN TestUploadHandlersRejectInvalidKeys763=== PAUSE TestUploadHandlersRejectInvalidKeys764=== RUN TestUploadHandlersRejectOversizedBody765=== PAUSE TestUploadHandlersRejectOversizedBody766=== RUN TestService_cleanupPendingClosuresHandler767=== PAUSE TestService_cleanupPendingClosuresHandler768=== RUN TestService_createPendingClosureHandler769=== PAUSE TestService_createPendingClosureHandler770=== RUN TestService_verifyS3Integrity771=== PAUSE TestService_verifyS3Integrity772=== RUN TestService_verifyS3ReuploadsStaleNarinfo773=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo774=== RUN TestCompleteMultipartUnregistered775=== PAUSE TestCompleteMultipartUnregistered776=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT777=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT778=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit779=== CONT TestPush_RepeatedRootCommitsOnce780=== CONT TestGCTaskStore_ConflictDifferentParams781=== CONT TestCommitRacingPendingCleanupKeepsObjects782=== CONT TestLeadUnannouncedStandbyYieldsToIncumbent783=== CONT TestService_RequireScope_OIDC784=== CONT TestTombstonedObjectOfferedWithoutWaiting785=== CONT TestAbortSucceeded786=== CONT TestPush_CompleteWaitsForCleanupOfThePush787--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)788--- PASS: TestAbortSucceeded (0.00s)789=== CONT TestCompleteMultipartUnregistered790=== CONT TestService_verifyS3ReuploadsStaleNarinfo791=== CONT TestProxyWriteTimeout792=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed793=== RUN TestProxyWriteTimeout/narinfo794=== CONT TestService_verifyS3Integrity795=== CONT TestService_createPendingClosureHandler796=== CONT TestService_cleanupPendingClosuresHandler797=== CONT TestUploadHandlersRejectOversizedBody798=== CONT TestUploadHandlersRejectInvalidKeys799=== CONT TestIsValidUploadKey800=== CONT TestPendingClosureWriteTimeout801=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info802=== RUN TestIsValidUploadKey/narinfo803=== CONT TestGCTaskStore_DeduplicateSameParams804=== CONT TestGCTaskStore_StartNew805=== CONT TestGCEndsOnShutdown806=== CONT TestClientIntegration807=== RUN TestPendingClosureWriteTimeout/empty808=== CONT TestOrphanedObjectsGCStressTest809=== CONT TestPush_RootsAreLockedInByteOrder810=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT811=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed812=== PAUSE TestProxyWriteTimeout/narinfo813=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info814--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)815--- PASS: TestGCTaskStore_StartNew (0.00s)816=== PAUSE TestPendingClosureWriteTimeout/empty817=== RUN TestPendingClosureWriteTimeout/400_objects818=== PAUSE TestPendingClosureWriteTimeout/400_objects819=== RUN TestPendingClosureWriteTimeout/670k_objects820=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed821=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed822=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost823=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost824=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed825=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed826=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal827=== RUN TestProxyWriteTimeout/1_GiB_nar828=== CONT TestPush_CompleteCommitsEveryRoot829=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed830=== PAUSE TestPendingClosureWriteTimeout/670k_objects831=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed832=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline833=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline834=== PAUSE TestIsValidUploadKey/narinfo835=== CONT TestPush_OverlappingRootsStoreOneRowPerKey836=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal837=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key838=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key839=== RUN TestGCEndsOnShutdown/before_the_run840=== PAUSE TestProxyWriteTimeout/1_GiB_nar841=== RUN TestProxyWriteTimeout/10_GiB_nar842=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key843=== CONT TestReadRedirectUsesPublicS3URL844=== CONT TestReadProxyRangeRequest845=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key846=== PAUSE TestProxyWriteTimeout/10_GiB_nar847=== CONT TestReadRedirectKeepsNarinfoProxied848=== RUN TestIsValidUploadKey/nar_zst849=== PAUSE TestIsValidUploadKey/nar_zst850=== RUN TestIsValidUploadKey/nar_xz851=== PAUSE TestIsValidUploadKey/nar_xz852=== RUN TestIsValidUploadKey/nar_plain853=== PAUSE TestIsValidUploadKey/nar_plain854=== RUN TestIsValidUploadKey/listing855=== PAUSE TestIsValidUploadKey/listing856=== RUN TestIsValidUploadKey/build_log857=== PAUSE TestIsValidUploadKey/build_log858=== RUN TestIsValidUploadKey/build_log_home-manager_file859=== PAUSE TestIsValidUploadKey/build_log_home-manager_file860=== RUN TestIsValidUploadKey/build_log_plus_in_name861=== PAUSE TestIsValidUploadKey/build_log_plus_in_name862=== RUN TestIsValidUploadKey/build_log_question_mark863=== PAUSE TestIsValidUploadKey/build_log_question_mark864=== RUN TestIsValidUploadKey/build_log_equals865=== PAUSE TestIsValidUploadKey/build_log_equals866=== RUN TestIsValidUploadKey/realisation867=== PAUSE TestIsValidUploadKey/realisation868=== RUN TestIsValidUploadKey/realisation_plus_in_output869=== PAUSE TestIsValidUploadKey/realisation_plus_in_output870=== RUN TestIsValidUploadKey/nix-cache-info871=== PAUSE TestIsValidUploadKey/nix-cache-info872=== RUN TestIsValidUploadKey/index.html873=== PAUSE TestIsValidUploadKey/index.html874=== RUN TestIsValidUploadKey/narinfo_key,_nar_type875=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type876=== RUN TestIsValidUploadKey/nar_key,_narinfo_type877=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type878=== RUN TestIsValidUploadKey/listing_key,_narinfo_type879=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type880=== RUN TestIsValidUploadKey/traversal881=== PAUSE TestIsValidUploadKey/traversal882=== RUN TestIsValidUploadKey/traversal_nar883=== PAUSE TestIsValidUploadKey/traversal_nar884=== RUN TestIsValidUploadKey/absolute885=== PAUSE TestIsValidUploadKey/absolute886=== RUN TestIsValidUploadKey/empty_key887=== PAUSE TestIsValidUploadKey/empty_key888=== RUN TestIsValidUploadKey/unknown_type889=== PAUSE TestIsValidUploadKey/unknown_type890=== RUN TestProxyWriteTimeout/unknown_size891=== PAUSE TestProxyWriteTimeout/unknown_size892=== CONT TestReadRedirectNar893=== CONT TestReadProxyDisabled894=== PAUSE TestGCEndsOnShutdown/before_the_run895=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete896=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete897=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark898=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark899=== CONT TestReadProxyRootRedirectsToIndexHTML900=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure901=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure902=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart903=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart904=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts905=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts906=== CONT TestReadProxyConditionalGet9072026/11/11 22:53:21 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56097/oidc9082026/11/11 22:53:21 INFO Received push request method=POST path=/api/pushes9092026/11/11 22:53:22 INFO Received complete push request method=POST path=/api/pushes/1/complete9102026/11/11 22:53:22 INFO Completed push id=1 objects=4 duration=103.292375ms911--- PASS: TestPush_RepeatedRootCommitsOnce (0.92s)912=== CONT TestReadProxyOutlastsServerWriteTimeout9132026/11/11 22:53:22 INFO lead: acquired remote=192.0.2.1:1234 generation=19142026/11/11 22:53:22 INFO Received push request method=POST path=/api/pushes9152026/11/11 22:53:22 INFO Received complete push request method=POST path=/api/pushes/1/complete9162026/11/11 22:53:22 INFO Completed push id=1 objects=4 duration=110.68875ms9172026/11/11 22:53:22 INFO Received push request method=POST path=/api/pushes9182026/11/11 22:53:22 INFO Received uploads request method=POST path=/api/pending_closures9192026/11/11 22:53:22 INFO Aborted multipart uploads count=0 kept=09202026/11/11 22:53:22 WARN Force mode enabled - objects will be deleted immediately without grace period9212026/11/11 22:53:22 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=09222026/11/11 22:53:23 INFO Vacuumed table table=pending_closures9232026/11/11 22:53:23 INFO Vacuumed table table=pending_objects9242026/11/11 22:53:23 INFO Vacuumed table table=multipart_uploads9252026/11/11 22:53:23 INFO Vacuumed table table=closures9262026/11/11 22:53:23 INFO Vacuumed table table=objects9272026/11/11 22:53:23 INFO Received complete push request method=POST path=/api/pushes/2/complete9282026/11/11 22:53:23 INFO Completed push id=2 objects=4 duration=7.82275ms929--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.97s)930=== CONT TestReadProxyHead9312026/11/11 22:53:23 INFO Aborted multipart uploads count=0 kept=09322026/11/11 22:53:23 INFO lead: released remote=192.0.2.1:1234 generation=19332026/11/11 22:53:23 WARN Force mode enabled - objects will be deleted immediately without grace period9342026/11/11 22:53:23 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=09352026/11/11 22:53:23 INFO lead: acquired remote=192.0.2.1:1234 generation=29362026/11/11 22:53:23 INFO Vacuumed table table=pending_closures9372026/11/11 22:53:23 INFO lead: given back to the incumbent remote=192.0.2.1:1234 generation=29382026/11/11 22:53:23 INFO lead: acquired remote=192.0.2.1:1234 generation=39392026/11/11 22:53:23 INFO Vacuumed table table=pending_objects9402026/11/11 22:53:23 INFO Vacuumed table table=multipart_uploads9412026/11/11 22:53:23 INFO Vacuumed table table=closures9422026/11/11 22:53:23 INFO Vacuumed table table=objects943--- PASS: TestCommitRacingPendingCleanupKeepsObjects (2.26s)944=== CONT TestReadProxyInvalidPath9452026/11/11 22:53:23 INFO Received push request method=POST path=/api/pushes9462026/11/11 22:53:23 INFO Received uploads request method=POST path=/api/pending_closures947--- PASS: TestTombstonedObjectOfferedWithoutWaiting (2.57s)948=== CONT TestReadProxy4049492026-11-11 22:53:23.916 UTC [69256] ERROR: Push does not exist: id=19502026-11-11 22:53:23.916 UTC [69256] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE9512026-11-11 22:53:23.916 UTC [69256] STATEMENT: SELECT commit_push($1)952--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (2.66s)953=== CONT TestReadProxyNarStreaming9542026/11/11 22:53:24 INFO Received cleanup request method=DELETE path=/api/pending_closures9552026/11/11 22:53:24 INFO Aborted multipart uploads count=0 kept=09562026/11/11 22:53:24 INFO Received uploads request method=POST path=/api/pending_closures9572026/11/11 22:53:24 INFO Received cleanup request method=DELETE path=/api/pending_closures9582026/11/11 22:53:24 INFO Aborted multipart uploads count=1 kept=09592026/11/11 22:53:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9602026-11-11 22:53:24.133 UTC [69225] ERROR: Closure does not exist: id=19612026-11-11 22:53:24.133 UTC [69225] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE9622026-11-11 22:53:24.133 UTC [69225] STATEMENT: -- name: CommitPendingClosure :one963 SELECT commit_pending_closure($1::bigint)::bigint964 965--- PASS: TestService_cleanupPendingClosuresHandler (2.87s)966=== CONT TestReadProxyContentNegotiation9672026/11/11 22:53:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete968=== NAME TestClientIntegration969 client_integration_test.go:291: Created store path: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientIntegration2956090003/002/store/sjfdqazjsjk2mwjzkcqn6rnp4z2i6mxz-test-file.txt9702026/11/11 22:53:24 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LmM3N2FjN2I3LTk4NjctNGFhNy1hMzU3LTAyM2Y4NGNmMjYxOXgxNzk0NDM3NjAyODg1MzU5MDAw parts=109712026/11/11 22:53:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9722026/11/11 22:53:24 INFO Completed upload id=1 objects=2 duration=6.854833ms9732026/11/11 22:53:24 INFO Received uploads request method=POST path=/api/pending_closures9742026/11/11 22:53:24 INFO Received uploads request method=POST path=/api/pending_closures9752026/11/11 22:53:24 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo9762026/11/11 22:53:24 WARN Found objects in DB but missing from S3, will re-upload count=1977--- PASS: TestService_verifyS3Integrity (3.17s)978=== CONT TestReadProxyNarinfoAlreadyDecompressed9792026/11/11 22:53:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9802026/11/11 22:53:24 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst981--- PASS: TestCompleteMultipartUnregistered (3.22s)982=== CONT TestReadProxyNarinfo9832026/11/11 22:53:24 INFO Received push request method=POST path=/api/pushes9842026/11/11 22:53:24 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)9852026/11/11 22:53:24 INFO Uploading sjfdqazjsjk2mwjzkcqn6rnp4z2i6mxz-test-file.txt (152B)9862026/11/11 22:53:24 WARN Failed to register uploaded object key=sjfdqazjsjk2mwjzkcqn6rnp4z2i6mxz.ls error="server returned 404: 404 page not found\n"9872026/11/11 22:53:24 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"9882026/11/11 22:53:24 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9892026/11/11 22:53:24 INFO Signed narinfos id=1 count=19902026/11/11 22:53:24 INFO Uploading 1 narinfos9912026/11/11 22:53:24 INFO Received complete push request method=POST path=/api/pushes/1/complete9922026/11/11 22:53:24 WARN Failed to register uploaded object key=sjfdqazjsjk2mwjzkcqn6rnp4z2i6mxz.narinfo error="server returned 404: 404 page not found\n"9932026/11/11 22:53:24 INFO Completed push id=1 objects=3 duration=16.885709ms9942026/11/11 22:53:24 INFO Upload complete. (185ms)9952026/11/11 22:53:24 INFO Received push request method=POST path=/api/pushes9962026/11/11 22:53:24 INFO All 1 paths already cached997=== NAME TestClientIntegration998 client_integration_test.go:317: Retrieved narinfo from S3:999 StorePath: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientIntegration2956090003/002/store/sjfdqazjsjk2mwjzkcqn6rnp4z2i6mxz-test-file.txt1000 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1001 Compression: zstd1002 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11003 NarSize: 1521004 References: 1005 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11006 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1007 client_integration_test.go:318: Decompressed .ls content (64 bytes):1008 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}10092026-11-11 22:53:24.775 UTC [69276] ERROR: could not obtain lock on row in relation "closures"10102026-11-11 22:53:24.775 UTC [69276] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10112026-11-11 22:53:24.780 UTC [69276] ERROR: could not obtain lock on row in relation "closures"10122026-11-11 22:53:24.780 UTC [69276] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10132026-11-11 22:53:24.781 UTC [69276] ERROR: could not obtain lock on row in relation "closures"10142026-11-11 22:53:24.781 UTC [69276] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10152026-11-11 22:53:24.782 UTC [69276] ERROR: could not obtain lock on row in relation "closures"10162026-11-11 22:53:24.782 UTC [69276] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10172026-11-11 22:53:24.788 UTC [69276] ERROR: could not obtain lock on row in relation "closures"10182026-11-11 22:53:24.788 UTC [69276] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1019--- PASS: TestPush_RootsAreLockedInByteOrder (3.53s)1020=== CONT TestIsValidCachePath1021=== RUN TestIsValidCachePath/narinfo1022=== PAUSE TestIsValidCachePath/narinfo1023=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1024=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1025=== RUN TestIsValidCachePath/nar_zst1026=== PAUSE TestIsValidCachePath/nar_zst1027=== RUN TestIsValidCachePath/nar_xz1028=== PAUSE TestIsValidCachePath/nar_xz1029=== RUN TestIsValidCachePath/nar_bz21030=== PAUSE TestIsValidCachePath/nar_bz21031=== RUN TestIsValidCachePath/nar_uncompressed1032=== PAUSE TestIsValidCachePath/nar_uncompressed1033=== RUN TestIsValidCachePath/ls1034=== PAUSE TestIsValidCachePath/ls1035=== RUN TestIsValidCachePath/log1036=== PAUSE TestIsValidCachePath/log1037=== RUN TestIsValidCachePath/realisation1038=== PAUSE TestIsValidCachePath/realisation1039=== RUN TestIsValidCachePath/nix-cache-info1040=== PAUSE TestIsValidCachePath/nix-cache-info1041=== RUN TestIsValidCachePath/index.html1042=== PAUSE TestIsValidCachePath/index.html1043=== RUN TestIsValidCachePath/traversal_parent1044=== PAUSE TestIsValidCachePath/traversal_parent1045=== RUN TestIsValidCachePath/traversal_in_middle1046=== PAUSE TestIsValidCachePath/traversal_in_middle1047=== RUN TestIsValidCachePath/invalid_char_e1048=== PAUSE TestIsValidCachePath/invalid_char_e1049=== RUN TestIsValidCachePath/invalid_char_u1050=== PAUSE TestIsValidCachePath/invalid_char_u1051=== RUN TestIsValidCachePath/random_path1052=== PAUSE TestIsValidCachePath/random_path1053=== RUN TestIsValidCachePath/empty1054=== PAUSE TestIsValidCachePath/empty1055=== RUN TestIsValidCachePath/leading_slash1056=== PAUSE TestIsValidCachePath/leading_slash1057=== RUN TestIsValidCachePath/wrong_extension1058=== PAUSE TestIsValidCachePath/wrong_extension1059=== RUN TestIsValidCachePath/short_hash1060=== PAUSE TestIsValidCachePath/short_hash1061=== CONT TestParseSingleRange1062=== RUN TestParseSingleRange/none1063=== PAUSE TestParseSingleRange/none1064=== RUN TestParseSingleRange/unknown_unit1065=== PAUSE TestParseSingleRange/unknown_unit1066=== RUN TestParseSingleRange/multi-range_ignored1067=== PAUSE TestParseSingleRange/multi-range_ignored1068=== RUN TestParseSingleRange/malformed_no_dash1069=== PAUSE TestParseSingleRange/malformed_no_dash1070=== RUN TestParseSingleRange/malformed_both_empty1071=== PAUSE TestParseSingleRange/malformed_both_empty1072=== RUN TestParseSingleRange/malformed_end_before_start1073=== PAUSE TestParseSingleRange/malformed_end_before_start1074=== RUN TestParseSingleRange/closed1075=== PAUSE TestParseSingleRange/closed1076=== RUN TestParseSingleRange/open-ended1077=== PAUSE TestParseSingleRange/open-ended1078=== RUN TestParseSingleRange/end_clamped_to_size1079=== PAUSE TestParseSingleRange/end_clamped_to_size1080=== RUN TestParseSingleRange/suffix1081=== PAUSE TestParseSingleRange/suffix1082=== RUN TestParseSingleRange/suffix_exceeds_size1083=== PAUSE TestParseSingleRange/suffix_exceeds_size1084=== RUN TestParseSingleRange/single_byte1085=== PAUSE TestParseSingleRange/single_byte1086=== RUN TestParseSingleRange/start_past_EOF1087=== PAUSE TestParseSingleRange/start_past_EOF1088=== RUN TestParseSingleRange/start_far_past_EOF1089=== PAUSE TestParseSingleRange/start_far_past_EOF1090=== CONT TestPresentNotReportedWhileGCDeletesClosure1091=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1092=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1093=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1094=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1095=== CONT TestPresentRefreshesOnlyStaleClosures10962026/11/11 22:53:24 INFO Received push request method=POST path=/api/pushes10972026/11/11 22:53:24 INFO Received complete push request method=POST path=/api/pushes/1/complete10982026/11/11 22:53:25 INFO Completed push id=1 objects=6 duration=36.620584ms1099--- PASS: TestPush_CompleteCommitsEveryRoot (3.74s)1100=== CONT TestPresentReportsOnlyClosureRoots11012026/11/11 22:53:25 INFO Received push request method=POST path=/api/pushes11022026/11/11 22:53:25 INFO Object in database but missing from S3 key=sjfdqazjsjk2mwjzkcqn6rnp4z2i6mxz.ls11032026/11/11 22:53:25 WARN Found objects in DB but missing from S3, will re-upload count=111042026/11/11 22:53:25 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11052026/11/11 22:53:25 INFO Received complete push request method=POST path=/api/pushes/2/complete11062026/11/11 22:53:25 WARN Failed to register uploaded object key=sjfdqazjsjk2mwjzkcqn6rnp4z2i6mxz.ls error="server returned 404: 404 page not found\n"11072026/11/11 22:53:25 INFO Completed push id=2 objects=3 duration=1.350916ms11082026/11/11 22:53:25 INFO Upload complete. (101ms)1109=== NAME TestClientIntegration1110 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1111 client_integration_test.go:335: Decompressed .ls content (49 bytes):1112 {"version":1,"root":{"type":"regular","size":39}}11132026/11/11 22:53:25 INFO Received uploads request method=POST path=/api/pending_closures11142026/11/11 22:53:25 INFO Received uploads request method=POST path=/api/pending_closures11152026/11/11 22:53:25 INFO Received uploads request method=POST path=/api/pending_closures11162026/11/11 22:53:25 INFO Received push request method=POST path=/api/pushes11172026/11/11 22:53:25 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11182026/11/11 22:53:25 INFO lead: released remote=192.0.2.1:1234 generation=31119--- PASS: TestLeadUnannouncedStandbyYieldsToIncumbent (4.11s)1120=== CONT TestCreatePin_ReservedPins11212026/11/11 22:53:25 INFO Received complete push request method=POST path=/api/pushes/3/complete11222026/11/11 22:53:25 WARN Failed to register uploaded object key=sjfdqazjsjk2mwjzkcqn6rnp4z2i6mxz.ls error="server returned 404: 404 page not found\n"11232026/11/11 22:53:25 INFO Completed push id=3 objects=3 duration=812.083µs11242026/11/11 22:53:25 INFO Upload complete. (109ms)1125=== NAME TestClientIntegration1126 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1127 client_integration_test.go:352: Decompressed .ls content (49 bytes):1128 {"version":1,"root":{"type":"regular","size":39}}1129 client_integration_test.go:363: Testing garbage collection...11302026/11/11 22:53:25 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56137/oidc11312026/11/11 22:53:25 INFO Received uploads request method=POST path=/api/pending_closures11322026/11/11 22:53:25 INFO Starting cleanup of old closures method=DELETE path=/api/closures11332026/11/11 22:53:25 INFO Garbage collection started11342026/11/11 22:53:25 INFO Aborted multipart uploads count=0 kept=011352026/11/11 22:53:25 WARN Force mode enabled - objects will be deleted immediately without grace period1136--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (4.20s)1137=== CONT TestClientFallsBackToClosures1138--- PASS: TestReadRedirectUsesPublicS3URL (4.49s)1139=== CONT TestLeadElectsOneAndHandsOver11402026/11/11 22:53:25 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=011412026/11/11 22:53:25 INFO Vacuumed table table=pending_closures11422026/11/11 22:53:25 INFO Vacuumed table table=pending_objects11432026/11/11 22:53:25 INFO Vacuumed table table=multipart_uploads11442026/11/11 22:53:25 INFO Vacuumed table table=closures11452026/11/11 22:53:25 INFO Vacuumed table table=objects1146--- PASS: TestReadProxyRangeRequest (4.80s)1147=== CONT TestConnectWaitsForAPeerMigration1148--- PASS: TestReadProxyDisabled (4.93s)1149=== CONT TestResolveDBConnectionString1150=== RUN TestResolveDBConnectionString/flag_wins1151=== PAUSE TestResolveDBConnectionString/flag_wins1152=== RUN TestResolveDBConnectionString/file_when_flag_empty1153=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1154=== RUN TestResolveDBConnectionString/missing_file_is_an_error1155=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1156=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1157=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1158=== RUN TestResolveDBConnectionString/nothing_configured1159=== PAUSE TestResolveDBConnectionString/nothing_configured1160=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock11612026/11/11 22:53:26 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1162--- PASS: TestReadProxyRootRedirectsToIndexHTML (5.19s)1163=== CONT TestDeleteClosuresRacingPins11642026/11/11 22:53:26 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LjE3YWY2YjMwLTExN2ItNDQ5NC1hNTA3LTFiZDkyOThhMjRjNXgxNzk0NDM3NjA1MTc1NjU2MDAw parts=1011652026/11/11 22:53:26 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11662026/11/11 22:53:26 INFO Completed upload id=1 objects=2 duration=11.198292ms11672026/11/11 22:53:26 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011682026/11/11 22:53:26 INFO Received uploads request method=POST path=/api/pending_closures11692026/11/11 22:53:26 INFO Starting cleanup of old closures method=DELETE path=/api/closures11702026/11/11 22:53:26 INFO Aborted multipart uploads count=0 kept=011712026/11/11 22:53:26 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=011722026/11/11 22:53:26 INFO Vacuumed table table=pending_closures11732026/11/11 22:53:26 INFO Vacuumed table table=pending_objects11742026/11/11 22:53:26 INFO Vacuumed table table=multipart_uploads11752026/11/11 22:53:26 INFO Vacuumed table table=closures11762026/11/11 22:53:26 INFO Vacuumed table table=objects11772026/11/11 22:53:26 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001178--- PASS: TestService_createPendingClosureHandler (5.51s)1179=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1180--- PASS: TestReadRedirectKeepsNarinfoProxied (5.67s)1181=== CONT TestService_AuthMiddleware_OIDC11822026/11/11 22:53:27 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56160/oidc1183--- PASS: TestReadRedirectNar (5.89s)1184=== CONT TestService_ReadAuthMiddleware11852026/11/11 22:53:27 INFO Received push request method=POST path=/api/pushes11862026/11/11 22:53:27 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01187=== NAME TestClientIntegration1188 client_integration_test.go:370: Objects in database after GC:1189 client_integration_test.go:370: Successfully deleted all objects with GC --force1190--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.24s)1191=== CONT TestCacheStatsHandler1192=== CONT TestClientErrorHandling1193--- PASS: TestClientIntegration (6.28s)1194=== RUN TestClientErrorHandling/InvalidStorePath1195=== PAUSE TestClientErrorHandling/InvalidStorePath1196=== RUN TestClientErrorHandling/InvalidAuthToken1197=== PAUSE TestClientErrorHandling/InvalidAuthToken1198=== RUN TestClientErrorHandling/ServerNotAvailable1199=== PAUSE TestClientErrorHandling/ServerNotAvailable1200=== CONT TestClientCADerivations1201--- PASS: TestReadProxyConditionalGet (6.36s)1202=== CONT TestCacheConfigHandler1203=== RUN TestCacheConfigHandler/full_config,_no_issuer1204=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1205=== RUN TestCacheConfigHandler/no_cache_url_configured1206=== PAUSE TestCacheConfigHandler/no_cache_url_configured1207=== RUN TestCacheConfigHandler/no_signing_keys1208=== PAUSE TestCacheConfigHandler/no_signing_keys1209=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1210=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1211=== CONT TestSweepSkipsRowsLockedByPush1212=== RUN TestService_RequireScope_OIDC/builder_may_write1213=== PAUSE TestService_RequireScope_OIDC/builder_may_write1214=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1215=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1216=== RUN TestService_RequireScope_OIDC/ops_may_admin1217=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1218=== RUN TestService_RequireScope_OIDC/ops_may_not_write1219=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1220=== RUN TestService_RequireScope_OIDC/reader_may_not_write1221=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1222=== RUN TestService_RequireScope_OIDC/static_token_may_admin1223=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1224=== RUN TestService_RequireScope_OIDC/static_token_may_write1225=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1226=== RUN TestService_RequireScope_OIDC/reader_may_read1227=== PAUSE TestService_RequireScope_OIDC/reader_may_read1228=== RUN TestService_RequireScope_OIDC/writer_implies_read1229=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1230=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1231=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1232=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1233=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1234=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1235=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1236=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1237=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1238=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1239=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1240=== CONT TestPushWaitsForSweepHoldingRow1241--- PASS: TestReadProxyHead (5.49s)1242=== CONT TestSweepRechecksPendingAfterLocking1243--- PASS: TestReadProxyInvalidPath (5.50s)1244=== CONT TestGetExistingObjectsLocksRows1245--- PASS: TestReadProxyNarStreaming (6.04s)1246=== CONT TestRegisterCompletedObjectNeedsPendingRow1247--- PASS: TestReadProxy404 (6.41s)1248=== CONT TestService_ReadScope_PublicByDefault1249--- PASS: TestReadProxyContentNegotiation (6.41s)1250=== CONT TestService_AuthMiddleware_MTLSProxyHeader1251--- PASS: TestReadProxyNarinfoAlreadyDecompressed (6.35s)1252=== CONT TestPresignedUploadRegisteredBeforeCommit12532026/11/11 22:53:31 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1254--- PASS: TestReadProxyNarinfo (6.75s)1255=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1256--- PASS: TestPresentRefreshesOnlyStaleClosures (6.68s)1257=== CONT TestSkippedUploadsHandler12582026/11/11 22:53:31 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001259--- PASS: TestSkippedUploadsHandler (0.01s)1260=== CONT TestParseSize1261--- PASS: TestParseSize (0.00s)1262=== CONT TestService_Rustfstest1263--- PASS: TestPresentReportsOnlyClosureRoots (6.82s)1264=== CONT TestForceGCDuringPushOffersSweptObject1265=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1266=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1267=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1268=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1269=== CONT TestFailedS3DeleteKeepsTombstone12702026/11/11 22:53:32 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12712026/11/11 22:53:32 WARN Refused reserved pin name=worker-x86_64-linux12722026/11/11 22:53:32 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12732026/11/11 22:53:32 INFO Received create pin request method=POST path=/api/pins/my-app12742026/11/11 22:53:32 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1275--- PASS: TestCreatePin_ReservedPins (7.05s)1276=== CONT TestSharedNarBothUploadsComplete1277--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.41s)1278=== CONT TestCompletedNarNotReofferedAcrossClosures12792026/11/11 22:53:32 INFO Received uploads request method=POST path=/api/pending_closures12802026/11/11 22:53:32 INFO Received uploads request method=POST path=/api/pending_closures12812026/11/11 22:53:32 INFO lead: acquired remote=192.0.2.1:1234 generation=112822026/11/11 22:53:32 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)12832026/11/11 22:53:32 INFO Uploading xrl5db3nh8fia8rj7ghp1rk3184l7pnc-b (256B)12842026/11/11 22:53:32 INFO Uploading ji70rfnp6da2vhqby6syc3nsqkarc2gi-shared-dep (136B)12852026/11/11 22:53:32 WARN Failed to register uploaded object key=nar/0x5gs2pcb4dbp7g665azc6licdlrrwhpi3cfg9m06kqys98v51pd.nar.zst error="server returned 404: 404 page not found\n"12862026/11/11 22:53:32 WARN Failed to register uploaded object key=dmz99nbpdslp5jwys76412sn1j1hq1h2.ls error="server returned 404: 404 page not found\n"12872026/11/11 22:53:32 WARN Failed to register uploaded object key=xrl5db3nh8fia8rj7ghp1rk3184l7pnc.ls error="server returned 404: 404 page not found\n"12882026/11/11 22:53:32 WARN Failed to register uploaded object key=ji70rfnp6da2vhqby6syc3nsqkarc2gi.ls error="server returned 404: 404 page not found\n"12892026/11/11 22:53:32 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign12902026/11/11 22:53:32 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12912026/11/11 22:53:32 INFO Signed narinfos id=1 count=212922026/11/11 22:53:32 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign12932026/11/11 22:53:32 INFO Signed narinfos id=2 count=212942026/11/11 22:53:32 INFO Uploading 4 narinfos12952026/11/11 22:53:32 WARN Failed to register uploaded object key=dmz99nbpdslp5jwys76412sn1j1hq1h2.narinfo error="server returned 404: 404 page not found\n"12962026/11/11 22:53:32 WARN Failed to register uploaded object key=ji70rfnp6da2vhqby6syc3nsqkarc2gi.narinfo error="server returned 404: 404 page not found\n"12972026/11/11 22:53:32 WARN Failed to register uploaded object key=xrl5db3nh8fia8rj7ghp1rk3184l7pnc.narinfo error="server returned 404: 404 page not found\n"1298--- PASS: TestConnectWaitsForAPeerMigration (6.80s)1299=== CONT TestCompleteMultipartUpload_ErrorButObjectExists13002026/11/11 22:53:32 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13012026/11/11 22:53:32 WARN Failed to register uploaded object key=ji70rfnp6da2vhqby6syc3nsqkarc2gi.narinfo error="server returned 404: 404 page not found\n"13022026/11/11 22:53:32 INFO Completed upload id=1 objects=6 duration=38.474125ms13032026/11/11 22:53:32 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13042026/11/11 22:53:32 INFO Completed upload id=2 objects=6 duration=765.542µs13052026/11/11 22:53:32 INFO Upload complete. (416ms)1306=== NAME TestClientFallsBackToClosures1307 client_pushes_test.go:112: Retrieved narinfo from S3:1308 StorePath: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientFallsBackToClosures3557407110/001/store/ji70rfnp6da2vhqby6syc3nsqkarc2gi-shared-dep1309 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1310 Compression: zstd1311 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821312 NarSize: 1361313 References: 1314 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1315 client_pushes_test.go:112: Retrieved narinfo from S3:1316 StorePath: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientFallsBackToClosures3557407110/001/store/dmz99nbpdslp5jwys76412sn1j1hq1h2-a1317 URL: nar/0x5gs2pcb4dbp7g665azc6licdlrrwhpi3cfg9m06kqys98v51pd.nar.zst1318 Compression: zstd1319 NarHash: sha256:0x5gs2pcb4dbp7g665azc6licdlrrwhpi3cfg9m06kqys98v51pd1320 NarSize: 2561321 References: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientFallsBackToClosures3557407110/001/store/ji70rfnp6da2vhqby6syc3nsqkarc2gi-shared-dep1322 CA: text:sha256:0asmd6ijqc4byxdf1sp0cabizwm7aa5zakgf26mmirjg09zz6l1c1323 client_pushes_test.go:112: Retrieved narinfo from S3:1324 StorePath: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientFallsBackToClosures3557407110/001/store/xrl5db3nh8fia8rj7ghp1rk3184l7pnc-b1325 URL: nar/0x5gs2pcb4dbp7g665azc6licdlrrwhpi3cfg9m06kqys98v51pd.nar.zst1326 Compression: zstd1327 NarHash: sha256:0x5gs2pcb4dbp7g665azc6licdlrrwhpi3cfg9m06kqys98v51pd1328 NarSize: 2561329 References: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientFallsBackToClosures3557407110/001/store/ji70rfnp6da2vhqby6syc3nsqkarc2gi-shared-dep1330 CA: text:sha256:0asmd6ijqc4byxdf1sp0cabizwm7aa5zakgf26mmirjg09zz6l1c1331--- PASS: TestClientFallsBackToClosures (7.57s)1332=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection13332026/11/11 22:53:33 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"13342026/11/11 22:53:33 WARN mTLS auth: bound subjects configured but subject DN unavailable13352026/11/11 22:53:33 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1336--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.85s)1337=== CONT TestService_AuthMiddleware1338=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1339=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1340=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1341=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1342=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1343=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1344=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1345=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1346=== CONT TestGCSweepDeliversEachKeyOnce13472026/11/11 22:53:33 INFO lead: released remote=192.0.2.1:1234 generation=113482026/11/11 22:53:33 INFO lead: acquired remote=192.0.2.1:1234 generation=21349--- PASS: TestService_ReadAuthMiddleware (6.96s)1350=== CONT TestClientSharedPathCommittedMidPush1351--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (7.97s)1352=== CONT TestClientPushesUseOnePush1353--- PASS: TestCacheStatsHandler (7.26s)1354=== CONT TestPinProtectsFromGC1355=== NAME TestClientCADerivations1356 client_ca_test.go:136: Built CA derivation: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientCADerivations4050106151/001/store/mkm4gi614sig294jbjkscv18qqavbhgf-ca-test1357 client_ca_test.go:139: Found 1 dependencies (including self)13582026/11/11 22:53:35 INFO Aborted multipart uploads count=0 kept=013592026/11/11 22:53:35 WARN Force mode enabled - objects will be deleted immediately without grace period13602026/11/11 22:53:35 INFO lead: released remote=192.0.2.1:1234 generation=21361--- PASS: TestLeadElectsOneAndHandsOver (9.26s)1362=== CONT TestPush_SignsNarinfosOfItsPendingObjects13632026/11/11 22:53:35 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=013642026/11/11 22:53:35 INFO Vacuumed table table=pending_closures13652026/11/11 22:53:35 INFO Vacuumed table table=pending_objects13662026/11/11 22:53:35 INFO Vacuumed table table=multipart_uploads13672026/11/11 22:53:35 INFO Vacuumed table table=closures13682026/11/11 22:53:35 INFO Vacuumed table table=objects13692026/11/11 22:53:35 INFO Aborted multipart uploads count=0 kept=013702026/11/11 22:53:35 INFO Received push request method=POST path=/api/pushes13712026/11/11 22:53:35 WARN Force mode enabled - objects will be deleted immediately without grace period13722026/11/11 22:53:35 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13732026/11/11 22:53:35 INFO Uploading mkm4gi614sig294jbjkscv18qqavbhgf-ca-test (144B)13742026/11/11 22:53:35 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"13752026/11/11 22:53:35 WARN Failed to register uploaded object key=mkm4gi614sig294jbjkscv18qqavbhgf.ls error="server returned 404: 404 page not found\n"13762026/11/11 22:53:35 WARN Failed to register uploaded object key=log/kwwka5i5facrablqn953bpkzs5k6whc7-ca-test.drv error="server returned 404: 404 page not found\n"13772026/11/11 22:53:35 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13782026/11/11 22:53:35 INFO Signed narinfos id=1 count=113792026/11/11 22:53:35 INFO Uploading 1 narinfos13802026/11/11 22:53:35 INFO Received uploads request method=POST path=/api/pending_closures13812026/11/11 22:53:35 INFO Received complete push request method=POST path=/api/pushes/1/complete13822026/11/11 22:53:35 WARN Failed to register uploaded object key=mkm4gi614sig294jbjkscv18qqavbhgf.narinfo error="server returned 404: 404 page not found\n"13832026/11/11 22:53:35 INFO Completed push id=1 objects=4 duration=39.210083ms13842026/11/11 22:53:35 INFO Upload complete. (325ms)1385=== NAME TestClientCADerivations1386 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientCADerivations4050106151/001/store/mkm4gi614sig294jbjkscv18qqavbhgf-ca-test1387 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1388 Compression: zstd1389 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1390 NarSize: 1441391 References: 1392 Deriver: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientCADerivations4050106151/001/store/kwwka5i5facrablqn953bpkzs5k6whc7-ca-test.drv1393 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1394 client_ca_test.go:185: Checking for realisation files in S3...1395 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1396 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache13972026/11/11 22:53:35 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=013982026/11/11 22:53:35 INFO Vacuumed table table=pending_closures13992026/11/11 22:53:35 INFO Vacuumed table table=pending_objects14002026/11/11 22:53:35 INFO Vacuumed table table=multipart_uploads14012026/11/11 22:53:35 INFO Vacuumed table table=closures14022026/11/11 22:53:35 INFO Vacuumed table table=objects1403--- PASS: TestSweepSkipsRowsLockedByPush (7.71s)1404=== CONT TestClientWithDependencies1405=== NAME TestClientCADerivations1406 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket46?endpoint=http://localhost:56080®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientCADerivations4050106151/001/store'1407 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11408--- PASS: TestClientCADerivations (8.02s)1409=== CONT TestClientMultipleUploads14102026/11/11 22:53:35 INFO Aborted multipart uploads count=0 kept=014112026/11/11 22:53:35 WARN Force mode enabled - objects will be deleted immediately without grace period14122026/11/11 22:53:35 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=014132026/11/11 22:53:35 INFO Vacuumed table table=pending_closures14142026/11/11 22:53:35 INFO Vacuumed table table=pending_objects14152026/11/11 22:53:35 INFO Vacuumed table table=multipart_uploads1416--- PASS: TestPushWaitsForSweepHoldingRow (7.81s)14172026/11/11 22:53:35 INFO Vacuumed table table=closures1418=== CONT TestCreatePendingClosureRejectsOversizedNAR14192026/11/11 22:53:35 INFO Received uploads request method=POST path=/api/pending_closures1420--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1421=== CONT TestOrphanedObjectsGC14222026/11/11 22:53:35 INFO Vacuumed table table=objects1423--- PASS: TestSweepRechecksPendingAfterLocking (7.09s)1424=== CONT TestObjectStatsUpdatedOncePerCommit1425--- PASS: TestGetExistingObjectsLocksRows (6.81s)1426=== CONT TestObjectStatsTrigger1427--- PASS: TestRegisterCompletedObjectNeedsPendingRow (6.11s)1428=== CONT TestPendingCleanupUsesOneCutoff1429--- PASS: TestService_ReadScope_PublicByDefault (6.07s)1430=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded14312026/11/11 22:53:36 INFO Received uploads request method=POST path=/api/pending_closures14322026/11/11 22:53:36 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst14332026/11/11 22:53:36 INFO Received uploads request method=POST path=/api/pending_closures1434--- PASS: TestPresignedUploadRegisteredBeforeCommit (5.96s)1435=== CONT TestMultipartCleanup1436--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.34s)1437=== CONT TestServerTLSConfig1438=== RUN TestServerTLSConfig/no_client_CA1439=== PAUSE TestServerTLSConfig/no_client_CA1440=== RUN TestServerTLSConfig/missing_CA_file1441=== PAUSE TestServerTLSConfig/missing_CA_file1442=== RUN TestServerTLSConfig/not_a_PEM_file1443=== PAUSE TestServerTLSConfig/not_a_PEM_file1444=== CONT TestService_NativeMTLS14452026/11/11 22:53:37 INFO Received uploads request method=POST path=/api/pending_closures1446--- PASS: TestDeleteClosuresRacingPins (10.95s)1447=== CONT TestMetricsCommit1448--- PASS: TestService_Rustfstest (5.99s)1449=== CONT TestMetricsInventory14502026/11/11 22:53:37 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14512026/11/11 22:53:37 INFO Received uploads request method=POST path=/api/pending_closures14522026/11/11 22:53:38 INFO Aborted multipart uploads count=0 kept=014532026/11/11 22:53:38 WARN Force mode enabled - objects will be deleted immediately without grace period14542026/11/11 22:53:38 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."14552026/11/11 22:53:38 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."14562026/11/11 22:53:38 INFO Received uploads request method=POST path=/api/pending_closures1457--- PASS: TestFailedS3DeleteKeepsTombstone (6.60s)1458=== CONT TestNARDeduplicationMetadataUploadBug14592026/11/11 22:53:38 INFO Received uploads request method=POST path=/api/pending_closures14602026/11/11 22:53:38 INFO Received uploads request method=POST path=/api/pending_closures1461=== NAME TestOrphanedObjectsGCStressTest1462 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains14632026/11/11 22:53:39 INFO Received uploads request method=POST path=/api/pending_closures1464 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion14652026/11/11 22:53:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14662026/11/11 22:53:39 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LjA3ODM5YzRkLTAyMTItNDk2MC1iN2NkLTk2YmU5M2VhMTFiOXgxNzk0NDM3NjE5NDQ3OTI0MDAw14672026/11/11 22:53:39 INFO Received uploads request method=POST path=/api/pending_closures14682026/11/11 22:53:39 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LjA3ODM5YzRkLTAyMTItNDk2MC1iN2NkLTk2YmU5M2VhMTFiOXgxNzk0NDM3NjE5NDQ3OTI0MDAw parts=11469--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (7.06s)1470=== CONT TestGracefulShutdownDrainsInflight14712026/11/11 22:53:39 INFO Starting HTTP server address=127.0.0.1:5625414722026/11/11 22:53:39 INFO Shutdown signal received, draining in-flight requests timeout=10s1473--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1474=== CONT TestCacheConfigHandlerMaxNarSize1475--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1476=== CONT TestEnsureAbortUploadsRule1477--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.09s)1478=== CONT TestGenerateLandingPage1479--- PASS: TestGenerateLandingPage (0.00s)1480=== CONT TestService_readinessHandler14812026/11/11 22:53:40 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1482--- PASS: TestService_AuthMiddleware (6.59s)1483=== CONT TestService_healthCheckHandler14842026/11/11 22:53:40 INFO Aborted multipart uploads count=0 kept=014852026/11/11 22:53:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14862026/11/11 22:53:41 WARN Force mode enabled - objects will be deleted immediately without grace period14872026/11/11 22:53:41 WARN Rate limiter enabled after throttle name=s3-test rate=514882026/11/11 22:53:41 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1489=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1490 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101491 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001492--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (9.93s)1493=== CONT TestGCTaskStore_CompletedAllowsNewTask1494--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1495=== CONT TestGCTaskStore_Fail1496--- PASS: TestGCTaskStore_Fail (0.00s)1497=== CONT TestGCTaskStore_PhaseUpdates1498--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1499=== CONT TestGCTaskStore_GetReturnsLatest1500--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1501=== CONT TestPush_RejectsBadRequests15022026/11/11 22:53:41 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LmYwOTY1NmJjLTA2NjctNDA1Ny1iOWE4LWE4ZTRiZDAzZmI5YXgxNzk0NDM3NjE4NTAzODU3MDAw parts=1215032026/11/11 22:53:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete15042026/11/11 22:53:41 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=015052026/11/11 22:53:41 INFO Vacuumed table table=pending_closures15062026/11/11 22:53:41 INFO Vacuumed table table=pending_objects15072026/11/11 22:53:41 INFO Vacuumed table table=multipart_uploads15082026/11/11 22:53:41 INFO Vacuumed table table=closures15092026/11/11 22:53:41 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LjM4Y2JhODM1LTFjZjUtNGVjNC1hYzhhLWMwZDZiM2M1MmU1MHgxNzk0NDM3NjE4OTQ4MjI0MDAw parts=1215102026/11/11 22:53:41 INFO Received uploads request method=POST path=/api/pending_closures1511--- PASS: TestCompletedNarNotReofferedAcrossClosures (9.07s)1512=== CONT TestGCBugBareHashReferences15132026/11/11 22:53:41 INFO Vacuumed table table=objects1514--- PASS: TestGCSweepDeliversEachKeyOnce (7.83s)1515=== CONT TestGCSweepSkipsPendingObjects15162026/11/11 22:53:42 INFO Received push request method=POST path=/api/pushes15172026/11/11 22:53:42 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)15182026/11/11 22:53:42 INFO Uploading vvasp4s58zn6j2hxvjn9gl83f02b8wvk-top (264B)15192026/11/11 22:53:42 INFO Uploading zjn28yqrwabhijp6pww82i6c9zmy0ycq-shared-dep (136B)15202026/11/11 22:53:42 WARN Failed to register uploaded object key=vvasp4s58zn6j2hxvjn9gl83f02b8wvk.ls error="server returned 404: 404 page not found\n"15212026/11/11 22:53:42 WARN Failed to register uploaded object key=zjn28yqrwabhijp6pww82i6c9zmy0ycq.ls error="server returned 404: 404 page not found\n"15222026/11/11 22:53:42 WARN Failed to register uploaded object key=nar/1wjncwsjcysr6df9690d66v71ckc34733l8yj12da4v2jwkn44wc.nar.zst error="server returned 404: 404 page not found\n"15232026/11/11 22:53:42 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15242026/11/11 22:53:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15252026/11/11 22:53:42 INFO Signed narinfos id=1 count=215262026/11/11 22:53:42 INFO Uploading 2 narinfos15272026/11/11 22:53:42 WARN Failed to register uploaded object key=zjn28yqrwabhijp6pww82i6c9zmy0ycq.narinfo error="server returned 404: 404 page not found\n"15282026/11/11 22:53:42 INFO Received complete push request method=POST path=/api/pushes/1/complete15292026/11/11 22:53:42 WARN Failed to register uploaded object key=vvasp4s58zn6j2hxvjn9gl83f02b8wvk.narinfo error="server returned 404: 404 page not found\n"15302026/11/11 22:53:42 INFO Completed push id=1 objects=6 duration=28.351959ms15312026/11/11 22:53:42 INFO Upload complete. (333ms)1532=== NAME TestClientSharedPathCommittedMidPush1533 client_integration_test.go:727: Retrieved narinfo from S3:1534 StorePath: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientSharedPathCommittedMidPush3225245010/001/store/zjn28yqrwabhijp6pww82i6c9zmy0ycq-shared-dep1535 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1536 Compression: zstd1537 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821538 NarSize: 1361539 References: 1540 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1541 client_integration_test.go:727: Retrieved narinfo from S3:1542 StorePath: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientSharedPathCommittedMidPush3225245010/001/store/vvasp4s58zn6j2hxvjn9gl83f02b8wvk-top1543 URL: nar/1wjncwsjcysr6df9690d66v71ckc34733l8yj12da4v2jwkn44wc.nar.zst1544 Compression: zstd1545 NarHash: sha256:1wjncwsjcysr6df9690d66v71ckc34733l8yj12da4v2jwkn44wc1546 NarSize: 2641547 References: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientSharedPathCommittedMidPush3225245010/001/store/zjn28yqrwabhijp6pww82i6c9zmy0ycq-shared-dep1548 CA: text:sha256:0mqn1fl9zgjxx7qla4w4vjrwz0g2gfvh0a7r229qg63n9ki54w1r15492026/11/11 22:53:42 INFO Received push request method=POST path=/api/pushes1550=== CONT TestDeduplicatedObjectsRecordedAsPending1551--- PASS: TestClientSharedPathCommittedMidPush (8.32s)15522026/11/11 22:53:42 INFO Received push request method=POST path=/api/pushes15532026/11/11 22:53:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15542026/11/11 22:53:42 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15552026/11/11 22:53:42 INFO Uploading 2s1jwmbynxxy39klp7agp91ksv0j266f-shared-dep (136B)15562026/11/11 22:53:42 INFO Uploading 0z6dpd2dzc1493hxx3iw9lhpj66ij2ba-b (256B)15572026/11/11 22:53:42 INFO Signed narinfos id=1 count=115582026/11/11 22:53:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15592026/11/11 22:53:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15602026/11/11 22:53:42 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"15612026/11/11 22:53:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15622026/11/11 22:53:42 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"15632026/11/11 22:53:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1564=== NAME TestPinProtectsFromGC1565 client_integration_test.go:778: Pinned store path: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestPinProtectsFromGC1815392565/001/store/88c56sqqj70dfm2q2j9sy65y7bbal2gh-pinned-file.txt1566 client_integration_test.go:779: Unpinned store path: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestPinProtectsFromGC1815392565/001/store/rvvzp4xgm2vc3g0xs3vd7bsq5gcrra32-unpinned-file.txt15672026/11/11 22:53:42 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=115682026/11/11 22:53:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15692026/11/11 22:53:42 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1570--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (7.53s)1571=== CONT TestPushDedupSurvivesConcurrentGC15722026/11/11 22:53:42 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15732026/11/11 22:53:42 WARN Failed to register uploaded object key=nym1w7fwa3ig6qwpgikfpl6lxdlhcdig.ls error="server returned 404: 404 page not found\n"15742026/11/11 22:53:42 WARN Failed to register uploaded object key=2s1jwmbynxxy39klp7agp91ksv0j266f.ls error="server returned 404: 404 page not found\n"15752026/11/11 22:53:42 WARN Failed to register uploaded object key=0z6dpd2dzc1493hxx3iw9lhpj66ij2ba.ls error="server returned 404: 404 page not found\n"15762026/11/11 22:53:42 WARN Failed to register uploaded object key=nar/040ymp13qpcq6a267c338y5q8yalsfcg2bsjjzblxsfy6n7m91fp.nar.zst error="server returned 404: 404 page not found\n"15772026/11/11 22:53:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15782026/11/11 22:53:42 INFO Signed narinfos id=1 count=315792026/11/11 22:53:42 INFO Uploading 3 narinfos15802026/11/11 22:53:42 WARN Failed to register uploaded object key=nym1w7fwa3ig6qwpgikfpl6lxdlhcdig.narinfo error="server returned 404: 404 page not found\n"15812026/11/11 22:53:42 INFO Received push request method=POST path=/api/pushes15822026/11/11 22:53:42 WARN Failed to register uploaded object key=0z6dpd2dzc1493hxx3iw9lhpj66ij2ba.narinfo error="server returned 404: 404 page not found\n"15832026/11/11 22:53:42 INFO Received complete push request method=POST path=/api/pushes/1/complete15842026/11/11 22:53:42 WARN Failed to register uploaded object key=2s1jwmbynxxy39klp7agp91ksv0j266f.narinfo error="server returned 404: 404 page not found\n"15852026/11/11 22:53:42 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15862026/11/11 22:53:42 INFO Uploading 88c56sqqj70dfm2q2j9sy65y7bbal2gh-pinned-file.txt (128B)15872026/11/11 22:53:42 INFO Completed push id=1 objects=8 duration=33.174875ms15882026/11/11 22:53:42 INFO Upload complete. (400ms)1589=== NAME TestClientPushesUseOnePush1590 client_pushes_test.go:97: Retrieved narinfo from S3:1591 StorePath: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientPushesUseOnePush3601727104/001/store/2s1jwmbynxxy39klp7agp91ksv0j266f-shared-dep1592 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1593 Compression: zstd1594 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821595 NarSize: 1361596 References: 1597 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1598 client_pushes_test.go:97: Retrieved narinfo from S3:1599 StorePath: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientPushesUseOnePush3601727104/001/store/nym1w7fwa3ig6qwpgikfpl6lxdlhcdig-a1600 URL: nar/040ymp13qpcq6a267c338y5q8yalsfcg2bsjjzblxsfy6n7m91fp.nar.zst1601 Compression: zstd1602 NarHash: sha256:040ymp13qpcq6a267c338y5q8yalsfcg2bsjjzblxsfy6n7m91fp1603 NarSize: 2561604 References: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientPushesUseOnePush3601727104/001/store/2s1jwmbynxxy39klp7agp91ksv0j266f-shared-dep1605 CA: text:sha256:03zlcdfsw4ah8n90ian1rmqqdbqrvdnp4caqpa05d67l78l00j151606 client_pushes_test.go:97: Retrieved narinfo from S3:1607 StorePath: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientPushesUseOnePush3601727104/001/store/0z6dpd2dzc1493hxx3iw9lhpj66ij2ba-b1608 URL: nar/040ymp13qpcq6a267c338y5q8yalsfcg2bsjjzblxsfy6n7m91fp.nar.zst1609 Compression: zstd1610 NarHash: sha256:040ymp13qpcq6a267c338y5q8yalsfcg2bsjjzblxsfy6n7m91fp1611 NarSize: 2561612 References: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientPushesUseOnePush3601727104/001/store/2s1jwmbynxxy39klp7agp91ksv0j266f-shared-dep1613 CA: text:sha256:03zlcdfsw4ah8n90ian1rmqqdbqrvdnp4caqpa05d67l78l00j1516142026/11/11 22:53:42 WARN Failed to register uploaded object key=88c56sqqj70dfm2q2j9sy65y7bbal2gh.ls error="server returned 404: 404 page not found\n"16152026/11/11 22:53:42 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16162026/11/11 22:53:42 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16172026/11/11 22:53:42 INFO Signed narinfos id=1 count=116182026/11/11 22:53:42 INFO Uploading 1 narinfos16192026/11/11 22:53:42 INFO Received complete push request method=POST path=/api/pushes/1/complete16202026/11/11 22:53:42 WARN Failed to register uploaded object key=88c56sqqj70dfm2q2j9sy65y7bbal2gh.narinfo error="server returned 404: 404 page not found\n"1621--- PASS: TestClientPushesUseOnePush (8.74s)1622=== CONT TestGCTaskStore_GetEmpty1623--- PASS: TestGCTaskStore_GetEmpty (0.00s)1624=== CONT TestGCMetrics16252026/11/11 22:53:42 INFO Completed push id=1 objects=3 duration=22.880458ms16262026/11/11 22:53:42 INFO Upload complete. (357ms)16272026/11/11 22:53:43 INFO Received push request method=POST path=/api/pushes16282026/11/11 22:53:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16292026/11/11 22:53:43 INFO Uploading rvvzp4xgm2vc3g0xs3vd7bsq5gcrra32-unpinned-file.txt (128B)16302026/11/11 22:53:43 WARN Failed to register uploaded object key=rvvzp4xgm2vc3g0xs3vd7bsq5gcrra32.ls error="server returned 404: 404 page not found\n"16312026/11/11 22:53:43 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16322026/11/11 22:53:43 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16332026/11/11 22:53:43 INFO Signed narinfos id=2 count=116342026/11/11 22:53:43 INFO Uploading 1 narinfos16352026/11/11 22:53:43 INFO Received complete push request method=POST path=/api/pushes/2/complete16362026/11/11 22:53:43 WARN Failed to register uploaded object key=rvvzp4xgm2vc3g0xs3vd7bsq5gcrra32.narinfo error="server returned 404: 404 page not found\n"16372026/11/11 22:53:43 INFO Completed push id=2 objects=3 duration=1.387834ms16382026/11/11 22:53:43 INFO Upload complete. (219ms)1639=== NAME TestClientMultipleUploads1640 client_integration_test.go:405: Created store path 0: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientMultipleUploads1973543036/001/store/fkw714dbblz888lfyg3vrhcq36iwq8m6-test-file-0.txt16412026/11/11 22:53:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures16422026/11/11 22:53:43 INFO Garbage collection started16432026/11/11 22:53:43 INFO Aborted multipart uploads count=0 kept=016442026/11/11 22:53:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete16452026/11/11 22:53:43 WARN Force mode enabled - objects will be deleted immediately without grace period1646 client_integration_test.go:405: Created store path 1: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientMultipleUploads1973543036/001/store/gpvx662xw7lysc1i5wi2cyrapsz61aj5-test-file-1.txt16472026/11/11 22:53:43 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LjkyYTIyMDg1LWI0M2MtNDhlMi04YzQ3LWU1NmJkYWU2YWJhNHgxNzk0NDM3NjE4NTcwNjAxMDAw parts=121648--- PASS: TestSharedNarBothUploadsComplete (11.13s)1649=== CONT TestLeadGenerationGrowsWithEveryGrant1650=== NAME TestClientMultipleUploads1651 client_integration_test.go:405: Created store path 2: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientMultipleUploads1973543036/001/store/6wradikb5idin2bzk1yq34gn1sa9qij2-test-file-2.txt16522026/11/11 22:53:43 INFO Received push request method=POST path=/api/pushes16532026/11/11 22:53:43 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)16542026/11/11 22:53:43 INFO Uploading 6wradikb5idin2bzk1yq34gn1sa9qij2-test-file-2.txt (160B)16552026/11/11 22:53:43 INFO Uploading fkw714dbblz888lfyg3vrhcq36iwq8m6-test-file-0.txt (160B)16562026/11/11 22:53:43 INFO Uploading gpvx662xw7lysc1i5wi2cyrapsz61aj5-test-file-1.txt (160B)16572026/11/11 22:53:43 WARN Failed to register uploaded object key=6wradikb5idin2bzk1yq34gn1sa9qij2.ls error="server returned 404: 404 page not found\n"16582026/11/11 22:53:43 WARN Failed to register uploaded object key=gpvx662xw7lysc1i5wi2cyrapsz61aj5.ls error="server returned 404: 404 page not found\n"16592026/11/11 22:53:43 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"16602026/11/11 22:53:43 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"16612026/11/11 22:53:43 WARN Failed to register uploaded object key=fkw714dbblz888lfyg3vrhcq36iwq8m6.ls error="server returned 404: 404 page not found\n"16622026/11/11 22:53:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16632026/11/11 22:53:43 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"16642026/11/11 22:53:43 INFO Signed narinfos id=1 count=316652026/11/11 22:53:43 INFO Uploading 3 narinfos16662026/11/11 22:53:44 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=016672026/11/11 22:53:44 WARN Failed to register uploaded object key=6wradikb5idin2bzk1yq34gn1sa9qij2.narinfo error="server returned 404: 404 page not found\n"16682026/11/11 22:53:44 INFO Received complete push request method=POST path=/api/pushes/1/complete16692026/11/11 22:53:44 WARN Failed to register uploaded object key=gpvx662xw7lysc1i5wi2cyrapsz61aj5.narinfo error="server returned 404: 404 page not found\n"16702026/11/11 22:53:44 WARN Failed to register uploaded object key=fkw714dbblz888lfyg3vrhcq36iwq8m6.narinfo error="server returned 404: 404 page not found\n"1671=== NAME TestClientWithDependencies1672 client_integration_test.go:660: Built derivation: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientWithDependencies2659781933/001/store/8mpwxn23gy4w3qi3vwznhnyf4p1s8xxp-test-script16732026/11/11 22:53:44 INFO Vacuumed table table=pending_closures16742026/11/11 22:53:44 INFO Completed push id=1 objects=9 duration=42.009ms16752026/11/11 22:53:44 INFO Upload complete. (412ms)1676=== NAME TestClientMultipleUploads1677 client_integration_test.go:416: Uploaded 3 paths in 445.555375ms16782026/11/11 22:53:44 INFO Vacuumed table table=pending_objects16792026/11/11 22:53:44 INFO Vacuumed table table=multipart_uploads1680=== NAME TestClientWithDependencies1681 client_integration_test.go:662: Found 1 dependencies (including self)16822026/11/11 22:53:44 INFO Vacuumed table table=closures1683--- PASS: TestClientMultipleUploads (8.57s)1684=== CONT TestLeadEndsOnShutdown16852026/11/11 22:53:44 INFO Vacuumed table table=objects16862026/11/11 22:53:44 INFO Received push request method=POST path=/api/pushes16872026/11/11 22:53:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16882026/11/11 22:53:44 INFO Uploading 8mpwxn23gy4w3qi3vwznhnyf4p1s8xxp-test-script (136B)16892026/11/11 22:53:44 WARN Failed to register uploaded object key=8mpwxn23gy4w3qi3vwznhnyf4p1s8xxp.ls error="server returned 404: 404 page not found\n"16902026/11/11 22:53:44 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"16912026/11/11 22:53:44 WARN Failed to register uploaded object key=log/8dv28qqvmnz1m6z0pcbarjan7v33cxsm-test-script.drv error="server returned 404: 404 page not found\n"16922026/11/11 22:53:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16932026/11/11 22:53:44 INFO Signed narinfos id=1 count=116942026/11/11 22:53:44 INFO Uploading 1 narinfos16952026/11/11 22:53:44 INFO Received complete push request method=POST path=/api/pushes/1/complete16962026/11/11 22:53:44 WARN Failed to register uploaded object key=8mpwxn23gy4w3qi3vwznhnyf4p1s8xxp.narinfo error="server returned 404: 404 page not found\n"16972026/11/11 22:53:44 INFO Completed push id=1 objects=4 duration=44.064375ms1698--- PASS: TestObjectStatsUpdatedOncePerCommit (8.67s)16992026/11/11 22:53:44 INFO Upload complete. (328ms)1700=== CONT TestGCAdvisoryLockBlocksConcurrentRun1701=== NAME TestClientWithDependencies1702 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestClientWithDependencies2659781933/001/store) requires matching store prefix1703--- PASS: TestClientWithDependencies (9.27s)1704=== CONT TestLeadIncumbentAnnouncesAtOnce1705--- PASS: TestObjectStatsTrigger (8.84s)1706=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed17072026/11/11 22:53:45 INFO Received uploads request method=POST path=/api/pending_closures17082026/11/11 22:53:45 INFO Received uploads request method=POST path=/api/pending_closures17092026/11/11 22:53:45 INFO Received cleanup request method=DELETE path=/api/pending_closures17102026/11/11 22:53:45 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=017112026/11/11 22:53:45 INFO Received create pin request method=POST path=/api/pins/myapp17122026/11/11 22:53:45 INFO Created/updated pin name=myapp store_path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestPinProtectsFromGC1815392565/001/store/88c56sqqj70dfm2q2j9sy65y7bbal2gh-pinned-file.txt narinfo_key=88c56sqqj70dfm2q2j9sy65y7bbal2gh.narinfo17132026/11/11 22:53:45 INFO Starting cleanup of old closures method=DELETE path=/api/closures17142026/11/11 22:53:45 INFO Garbage collection started17152026/11/11 22:53:45 INFO Aborted multipart uploads count=0 kept=017162026/11/11 22:53:45 WARN Force mode enabled - objects will be deleted immediately without grace period17172026/11/11 22:53:45 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=017182026/11/11 22:53:45 INFO Vacuumed table table=pending_closures17192026/11/11 22:53:45 INFO Vacuumed table table=pending_objects17202026/11/11 22:53:45 INFO Vacuumed table table=multipart_uploads17212026/11/11 22:53:45 INFO Vacuumed table table=closures17222026/11/11 22:53:45 INFO Vacuumed table table=objects17232026/11/11 22:53:45 INFO Received uploads request method=POST path=/api/pending_closures1724--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (9.39s)1725=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed17262026/11/11 22:53:46 INFO Received uploads request method=POST path=/api/pending_closures1727=== NAME TestOrphanedObjectsGC1728 orphaned_objects_gc_test.go:287: GC Test Summary:17292026/11/11 22:53:46 INFO Received cleanup request method=DELETE path=/api/pending_closures1730 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1731 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1732 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1733 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1734 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1735--- PASS: TestOrphanedObjectsGC (10.74s)1736=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed17372026/11/11 22:53:46 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket76/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""17382026/11/11 22:53:46 INFO Aborted multipart uploads count=0 kept=117392026/11/11 22:53:46 INFO Received cleanup request method=DELETE path=/api/pending_closures17402026/11/11 22:53:46 INFO Aborted multipart uploads count=1 kept=01741--- PASS: TestMultipartCleanup (9.83s)1742=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost17432026/11/11 22:53:46 WARN mTLS auth: subject not in bound subjects subject="CN=reader"17442026/11/11 22:53:46 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1745--- PASS: TestService_NativeMTLS (9.86s)1746=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed17472026/11/11 22:53:47 INFO Received push request method=POST path=/api/pushes17482026/11/11 22:53:47 INFO Received complete push request method=POST path=/api/pushes/1/complete17492026/11/11 22:53:47 INFO Completed push id=1 objects=4 duration=50.567875ms17502026/11/11 22:53:47 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17512026/11/11 22:53:47 INFO Completed upload id=2 objects=2 duration=2.843542ms1752--- PASS: TestMetricsCommit (9.97s)1753=== CONT TestPendingClosureWriteTimeout/empty1754=== CONT TestPendingClosureWriteTimeout/670k_objects1755=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1756=== NAME TestPinProtectsFromGC1757 client_integration_test.go:887: Pin successfully protected closure from garbage collection1758--- PASS: TestPinProtectsFromGC (12.80s)1759=== CONT TestPendingClosureWriteTimeout/400_objects1760=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17612026/11/11 22:53:47 INFO Received uploads request method=POST path=/1762=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17632026/11/11 22:53:47 INFO Received request for more parts method=POST path=/1764=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17652026/11/11 22:53:47 INFO Received complete multipart upload request method=POST path=/1766=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17672026/11/11 22:53:47 INFO Received uploads request method=POST path=/1768--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1769 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1770 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.01s)1771 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1772 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1773=== CONT TestIsValidUploadKey/narinfo1774=== CONT TestProxyWriteTimeout/narinfo1775=== CONT TestIsValidUploadKey/build_log_equals1776=== CONT TestIsValidUploadKey/unknown_type1777=== CONT TestIsValidUploadKey/empty_key1778=== CONT TestIsValidUploadKey/absolute1779=== CONT TestIsValidUploadKey/traversal_nar1780=== CONT TestIsValidUploadKey/traversal1781=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1782=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1783=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1784=== CONT TestIsValidUploadKey/index.html1785=== CONT TestIsValidUploadKey/nix-cache-info1786=== CONT TestIsValidUploadKey/realisation_plus_in_output1787=== CONT TestIsValidUploadKey/realisation1788=== CONT TestIsValidUploadKey/nar_xz1789=== CONT TestIsValidUploadKey/build_log_question_mark1790=== CONT TestIsValidUploadKey/build_log_plus_in_name1791=== CONT TestIsValidUploadKey/build_log_home-manager_file1792=== CONT TestIsValidUploadKey/build_log1793=== CONT TestIsValidUploadKey/listing1794=== CONT TestIsValidUploadKey/nar_plain1795=== CONT TestIsValidUploadKey/nar_zst1796--- PASS: TestIsValidUploadKey (0.05s)1797 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1798 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1799 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1800 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1801 --- PASS: TestIsValidUploadKey/absolute (0.00s)1802 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1803 --- PASS: TestIsValidUploadKey/traversal (0.00s)1804 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1805 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1806 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1807 --- PASS: TestIsValidUploadKey/index.html (0.00s)1808 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1809 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1810 --- PASS: TestIsValidUploadKey/realisation (0.00s)1811 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1812 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1813 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1814 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1815 --- PASS: TestIsValidUploadKey/build_log (0.00s)1816 --- PASS: TestIsValidUploadKey/listing (0.00s)1817 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1818 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1819=== CONT TestGCEndsOnShutdown/before_the_run1820--- PASS: TestMetricsInventory (10.15s)1821=== CONT TestProxyWriteTimeout/10_GiB_nar1822=== CONT TestProxyWriteTimeout/unknown_size1823=== CONT TestProxyWriteTimeout/1_GiB_nar1824=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1825--- PASS: TestProxyWriteTimeout (0.05s)1826 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1827 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1828 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1829 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1830=== NAME TestNARDeduplicationMetadataUploadBug1831 metadata_upload_test.go:48: First store path: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestNARDeduplicationMetadataUploadBug847913197/001/store/1s586s03jz8hag5lg4w88qrr19dk391g-file1.txt18322026/11/11 22:53:48 INFO Installed lifecycle rule aborting incomplete NAR uploads bucket=bucket81 days=21833--- PASS: TestEnsureAbortUploadsRule (8.47s)1834=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark18352026/11/11 22:53:48 INFO Received push request method=POST path=/api/pushes18362026/11/11 22:53:48 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18372026/11/11 22:53:48 INFO Uploading 1s586s03jz8hag5lg4w88qrr19dk391g-file1.txt (160B)1838--- PASS: TestService_healthCheckHandler (8.49s)1839=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18402026/11/11 22:53:48 INFO Received uploads request method=POST path=/18412026/11/11 22:53:48 WARN Failed to register uploaded object key=1s586s03jz8hag5lg4w88qrr19dk391g.ls error="server returned 404: 404 page not found\n"18422026/11/11 22:53:48 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18432026/11/11 22:53:48 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"18442026/11/11 22:53:48 INFO Signed narinfos id=1 count=118452026/11/11 22:53:48 INFO Uploading 1 narinfos18462026/11/11 22:53:48 INFO Received complete push request method=POST path=/api/pushes/1/complete18472026/11/11 22:53:48 WARN Failed to register uploaded object key=1s586s03jz8hag5lg4w88qrr19dk391g.narinfo error="server returned 404: 404 page not found\n"18482026/11/11 22:53:48 INFO Completed push id=1 objects=3 duration=24.410208ms18492026/11/11 22:53:48 INFO Upload complete. (239ms)1850=== NAME TestNARDeduplicationMetadataUploadBug1851 metadata_upload_test.go:54: Retrieved narinfo from S3:1852 StorePath: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestNARDeduplicationMetadataUploadBug847913197/001/store/1s586s03jz8hag5lg4w88qrr19dk391g-file1.txt1853 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1854 Compression: zstd1855 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1856 NarSize: 1601857 References: 1858 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1859 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1860 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1861 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1862 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestNARDeduplicationMetadataUploadBug847913197/001/store/xqn0pz6ggvamna3qhqdn8kqzrgkbh42b-file2.txt1863=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18642026/11/11 22:53:49 INFO Received request for more parts method=POST path=/18652026/11/11 22:53:49 INFO Received push request method=POST path=/api/pushes18662026/11/11 22:53:49 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)18672026/11/11 22:53:49 WARN readiness check failed error="closed pool"1868--- PASS: TestService_readinessHandler (8.88s)1869=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18702026/11/11 22:53:49 INFO Received complete multipart upload request method=POST path=/1871=== CONT TestIsValidCachePath/narinfo1872=== CONT TestIsValidCachePath/index.html1873=== CONT TestIsValidCachePath/short_hash1874=== CONT TestIsValidCachePath/wrong_extension1875=== CONT TestIsValidCachePath/leading_slash1876=== CONT TestIsValidCachePath/empty1877=== CONT TestIsValidCachePath/random_path1878=== CONT TestIsValidCachePath/invalid_char_u1879=== CONT TestIsValidCachePath/invalid_char_e1880=== CONT TestIsValidCachePath/traversal_in_middle1881=== CONT TestIsValidCachePath/traversal_parent1882=== CONT TestIsValidCachePath/nar_uncompressed1883=== CONT TestIsValidCachePath/nix-cache-info1884=== CONT TestIsValidCachePath/realisation1885=== CONT TestIsValidCachePath/log1886=== CONT TestIsValidCachePath/ls1887=== CONT TestIsValidCachePath/nar_xz1888=== CONT TestIsValidCachePath/nar_bz21889=== CONT TestIsValidCachePath/nar_zst1890=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1891--- PASS: TestIsValidCachePath (0.01s)1892 --- PASS: TestIsValidCachePath/narinfo (0.00s)1893 --- PASS: TestIsValidCachePath/index.html (0.00s)1894 --- PASS: TestIsValidCachePath/short_hash (0.00s)1895 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1896 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1897 --- PASS: TestIsValidCachePath/empty (0.00s)1898 --- PASS: TestIsValidCachePath/random_path (0.00s)1899 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1900 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1901 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1902 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1903 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1904 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1905 --- PASS: TestIsValidCachePath/realisation (0.00s)1906 --- PASS: TestIsValidCachePath/log (0.00s)1907 --- PASS: TestIsValidCachePath/ls (0.00s)1908 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1909 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1910 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1911 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1912=== CONT TestParseSingleRange/none1913=== CONT TestParseSingleRange/open-ended1914=== CONT TestParseSingleRange/start_far_past_EOF1915=== CONT TestParseSingleRange/start_past_EOF1916=== CONT TestParseSingleRange/single_byte1917=== CONT TestParseSingleRange/suffix_exceeds_size1918=== CONT TestParseSingleRange/suffix1919=== CONT TestParseSingleRange/end_clamped_to_size1920=== CONT TestParseSingleRange/malformed_both_empty1921=== CONT TestParseSingleRange/closed1922=== CONT TestParseSingleRange/malformed_end_before_start1923=== CONT TestParseSingleRange/multi-range_ignored1924=== CONT TestParseSingleRange/malformed_no_dash1925=== CONT TestParseSingleRange/unknown_unit1926--- PASS: TestParseSingleRange (0.01s)1927 --- PASS: TestParseSingleRange/none (0.00s)1928 --- PASS: TestParseSingleRange/open-ended (0.00s)1929 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1930 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1931 --- PASS: TestParseSingleRange/single_byte (0.00s)1932 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1933 --- PASS: TestParseSingleRange/suffix (0.00s)1934 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1935 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1936 --- PASS: TestParseSingleRange/closed (0.00s)1937 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1938 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1939 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1940 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1941=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1942--- PASS: TestUploadHandlersRejectOversizedBody (0.07s)1943 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)1944 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1945 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1946=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh19472026/11/11 22:53:49 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign19482026/11/11 22:53:49 WARN Failed to register uploaded object key=xqn0pz6ggvamna3qhqdn8kqzrgkbh42b.ls error="server returned 404: 404 page not found\n"19492026/11/11 22:53:49 INFO Signed narinfos id=2 count=119502026/11/11 22:53:49 INFO Uploading 1 narinfos19512026/11/11 22:53:49 INFO Received complete push request method=POST path=/api/pushes/2/complete19522026/11/11 22:53:49 WARN Failed to register uploaded object key=xqn0pz6ggvamna3qhqdn8kqzrgkbh42b.narinfo error="server returned 404: 404 page not found\n"19532026/11/11 22:53:49 INFO Completed push id=2 objects=3 duration=1.04825ms19542026/11/11 22:53:49 INFO Upload complete. (173ms)1955=== NAME TestNARDeduplicationMetadataUploadBug1956 metadata_upload_test.go:76: Retrieved narinfo from S3:1957 StorePath: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestNARDeduplicationMetadataUploadBug847913197/001/store/xqn0pz6ggvamna3qhqdn8kqzrgkbh42b-file2.txt1958 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1959 Compression: zstd1960 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1961 NarSize: 1601962 References: 1963 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1964 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1965 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1966 {"version":1,"root":{"type":"regular","size":44}}1967--- PASS: TestNARDeduplicationMetadataUploadBug (10.81s)1968=== CONT TestResolveDBConnectionString/flag_wins1969=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1970=== CONT TestResolveDBConnectionString/nothing_configured1971=== CONT TestResolveDBConnectionString/missing_file_is_an_error1972=== CONT TestResolveDBConnectionString/file_when_flag_empty1973=== CONT TestClientErrorHandling/InvalidStorePath1974--- PASS: TestResolveDBConnectionString (0.03s)1975 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1976 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1977 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1978 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1979 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1980=== RUN TestPush_RejectsBadRequests/no_roots1981=== PAUSE TestPush_RejectsBadRequests/no_roots1982=== RUN TestPush_RejectsBadRequests/no_objects1983=== PAUSE TestPush_RejectsBadRequests/no_objects1984=== RUN TestPush_RejectsBadRequests/bad_root1985=== PAUSE TestPush_RejectsBadRequests/bad_root1986=== RUN TestPush_RejectsBadRequests/root_not_in_objects1987=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1988=== CONT TestClientErrorHandling/ServerNotAvailable19892026/11/11 22:53:49 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19902026/11/11 22:53:49 INFO Received uploads request method=POST path=/api/pending_closures19912026/11/11 22:53:49 INFO Aborted multipart uploads count=0 kept=019922026/11/11 22:53:49 WARN Request failed, retrying attempt=2 backoff=207.26874ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19932026/11/11 22:53:49 WARN Force mode enabled - objects will be deleted immediately without grace period19942026/11/11 22:53:49 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=019952026/11/11 22:53:49 INFO Vacuumed table table=pending_closures19962026/11/11 22:53:49 INFO Vacuumed table table=pending_objects19972026/11/11 22:53:49 INFO Vacuumed table table=multipart_uploads19982026/11/11 22:53:49 INFO Vacuumed table table=closures19992026/11/11 22:53:49 INFO Vacuumed table table=objects2000--- PASS: TestGCSweepSkipsPendingObjects (8.24s)2001=== CONT TestClientErrorHandling/InvalidAuthToken20022026/11/11 22:53:50 WARN Request failed, retrying attempt=3 backoff=385.737173ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20032026/11/11 22:53:50 WARN Request failed, retrying attempt=4 backoff=872.848461ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2004--- PASS: TestGCBugBareHashReferences (8.77s)2005=== CONT TestCacheConfigHandler/full_config,_no_issuer2006=== CONT TestCacheConfigHandler/no_signing_keys2007=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2008=== CONT TestCacheConfigHandler/no_cache_url_configured2009--- PASS: TestCacheConfigHandler (0.00s)2010 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2011 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2012 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2013 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2014=== CONT TestService_RequireScope_OIDC/builder_may_write2015=== CONT TestService_RequireScope_OIDC/reader_may_read2016=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2017=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20182026/11/11 22:53:50 INFO Received uploads request method=POST path=/api/pending_closures20192026/11/11 22:53:50 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]2020=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2021=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2022=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2023=== CONT TestService_RequireScope_OIDC/writer_implies_read2024=== CONT TestService_RequireScope_OIDC/reader_may_not_write2025=== CONT TestService_RequireScope_OIDC/static_token_may_write2026=== CONT TestService_RequireScope_OIDC/static_token_may_admin2027=== CONT TestService_RequireScope_OIDC/ops_may_admin2028=== CONT TestService_RequireScope_OIDC/ops_may_not_write2029=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2030=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows2031--- PASS: TestService_RequireScope_OIDC (6.71s)2032 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2033 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2034 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2035 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.01s)2036 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2037 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2038 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2039 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2040 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2041 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2042 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2043 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2044 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2045 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2046--- PASS: TestDeduplicatedObjectsRecordedAsPending (8.04s)2047=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check20482026/11/11 22:53:51 INFO Received uploads request method=POST path=/api/pending_closures20492026/11/11 22:53:51 INFO Aborted multipart uploads count=1 kept=020502026/11/11 22:53:51 WARN Request failed, retrying attempt=5 backoff=1.549873809s error="Post \"http://localhost:19999/api/objects/present\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20512026/11/11 22:53:51 INFO Received cleanup request method=DELETE path=/api/pending_closures20522026/11/11 22:53:51 INFO Aborted multipart uploads count=1 kept=020532026/11/11 22:53:51 INFO Aborted multipart uploads count=0 kept=020542026/11/11 22:53:51 INFO Aborted multipart uploads count=0 kept=02055--- PASS: TestPendingCleanupUsesOneCutoff (15.30s)20562026/11/11 22:53:51 WARN Force mode enabled - objects will be deleted immediately without grace period2057=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2058=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20592026/11/11 22:53: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=020602026/11/11 22:53:51 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]20612026/11/11 22:53:51 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=02062=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2063=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20642026/11/11 22:53:51 WARN Authentication failed token_preview=eyJhbGciOi...li7si4xMqg token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]20652026/11/11 22:53:51 INFO Vacuumed table table=pending_closures2066=== CONT TestServerTLSConfig/no_client_CA20672026/11/11 22:53:51 INFO Vacuumed table table=pending_objects2068=== CONT TestServerTLSConfig/not_a_PEM_file20692026/11/11 22:53:51 INFO Vacuumed table table=multipart_uploads2070--- PASS: TestService_AuthMiddleware_OIDC (6.92s)2071 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2072 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.01s)2073 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2074 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)20752026/11/11 22:53:51 INFO Vacuumed table table=closures20762026/11/11 22:53:51 INFO Vacuumed table table=objects20772026/11/11 22:53:51 INFO Vacuumed table table=pending_closures2078--- PASS: TestGCMetrics (8.46s)2079=== CONT TestServerTLSConfig/missing_CA_file2080=== CONT TestPush_RejectsBadRequests/no_roots20812026/11/11 22:53:51 INFO Received push request method=POST path=/api/pushes2082=== CONT TestPush_RejectsBadRequests/bad_root20832026/11/11 22:53:51 INFO Received push request method=POST path=/api/pushes2084=== CONT TestPush_RejectsBadRequests/root_not_in_objects20852026/11/11 22:53:51 INFO Received push request method=POST path=/api/pushes2086=== CONT TestPush_RejectsBadRequests/no_objects20872026/11/11 22:53:51 INFO Received push request method=POST path=/api/pushes2088--- PASS: TestPush_RejectsBadRequests (8.16s)2089 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)2090 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)2091 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)2092 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)2093--- PASS: TestServerTLSConfig (0.00s)2094 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2095 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2096 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)20972026/11/11 22:53:51 INFO Vacuumed table table=pending_objects20982026/11/11 22:53:51 INFO Vacuumed table table=multipart_uploads20992026/11/11 22:53:51 INFO Vacuumed table table=closures21002026/11/11 22:53:51 INFO Vacuumed table table=objects21012026/11/11 22:53:51 INFO Aborted multipart uploads count=0 kept=021022026/11/11 22:53:51 WARN Force mode enabled - objects will be deleted immediately without grace period21032026/11/11 22:53: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=021042026/11/11 22:53:51 INFO Vacuumed table table=pending_closures21052026/11/11 22:53:51 INFO Vacuumed table table=pending_objects21062026/11/11 22:53:51 INFO Vacuumed table table=multipart_uploads21072026/11/11 22:53:51 INFO Vacuumed table table=closures21082026/11/11 22:53:51 INFO Vacuumed table table=objects2109--- PASS: TestPushDedupSurvivesConcurrentGC (9.10s)21102026/11/11 22:53:51 INFO lead: acquired remote=192.0.2.1:1234 generation=121112026-11-11 22:53:52.175 UTC [69127] LOG: checkpoint starting: wal21122026/11/11 22:53:52 INFO lead: acquired remote=192.0.2.1:1234 generation=121132026/11/11 22:53:52 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld5 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"2114--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (8.03s)21152026/11/11 22:53:52 INFO lead: acquired remote=192.0.2.1:1234 generation=121162026/11/11 22:53:52 INFO lead: released remote=192.0.2.1:1234 generation=12117--- PASS: TestLeadIncumbentAnnouncesAtOnce (8.15s)21182026/11/11 22:53:52 INFO lead: released remote=192.0.2.1:1234 generation=121192026/11/11 22:53:52 INFO lead: acquired remote=192.0.2.1:1234 generation=221202026/11/11 22:53:52 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21212026/11/11 22:53:53 WARN Request failed, retrying attempt=2 backoff=186.616959ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21222026/11/11 22:53:53 INFO Received uploads request method=POST path=/api/pending_closures21232026/11/11 22:53:53 WARN Request failed, retrying attempt=3 backoff=388.783932ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21242026/11/11 22:53:53 INFO lead: released remote=192.0.2.1:1234 generation=12125--- PASS: TestLeadEndsOnShutdown (9.16s)21262026/11/11 22:53:53 INFO Received uploads request method=POST path=/api/pending_closures21272026/11/11 22:53:53 WARN Request failed, retrying attempt=4 backoff=840.774621ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21282026/11/11 22:53:53 INFO Received uploads request method=POST path=/api/pending_closures21292026/11/11 22:53:53 INFO Received uploads request method=POST path=/api/pending_closures21302026/11/11 22:53:54 INFO lead: released remote=192.0.2.1:1234 generation=221312026/11/11 22:53:54 INFO lead: acquired remote=192.0.2.1:1234 generation=321322026/11/11 22:53:54 INFO lead: released remote=192.0.2.1:1234 generation=32133--- PASS: TestLeadGenerationGrowsWithEveryGrant (10.48s)21342026/11/11 22:53:54 INFO Received uploads request method=POST path=/api/pending_closures21352026/11/11 22:53:54 WARN Request failed, retrying attempt=5 backoff=1.486918416s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21362026/11/11 22:53:54 INFO Received uploads request method=POST path=/api/pending_closures21372026/11/11 22:53:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21382026/11/11 22:53:54 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LjI5ZmQ4NTBiLWQ0MjUtNGM4MC04ZjllLTg2ZDU1NTUxZDE4ZHgxNzk0NDM3NjMzMDg4ODc4MDAw parts=1021392026/11/11 22:53:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21402026/11/11 22:53:54 INFO Completed upload id=1 objects=3 duration=12.633625ms21412026/11/11 22:53:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21422026/11/11 22:53:55 INFO Aborted multipart uploads count=0 kept=021432026/11/11 22:53:55 WARN Force mode enabled - objects will be deleted immediately without grace period21442026/11/11 22:53:55 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:56080/bucket100/?delete=\": context canceled"21452026/11/11 22:53:55 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LjNjZTllYWE4LTQwOGMtNDhkZC1hYmRmLWQ0ZjE5MzUxYmVkZngxNzk0NDM3NjMzMzU5NTUwMDAw parts=1021462026/11/11 22:53:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21472026/11/11 22:53:55 INFO Completed upload id=1 objects=3 duration=9.205209ms21482026/11/11 22:53:55 INFO Received uploads request method=POST path=/api/pending_closures21492026/11/11 22:53:55 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21502026/11/11 22:53:55 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21512026/11/11 22:53:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2152--- PASS: TestPendingClosureWriteTimeout (0.00s)2153 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2154 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2155 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2156 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (8.07s)21572026/11/11 22:53:55 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LjdlZjY0NTI0LWU0NjMtNGMwOC04Yjc5LWY3YmVmOTZjMWE3ZngxNzk0NDM3NjMzNjYzMzI0MDAw parts=1021582026/11/11 22:53:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21592026/11/11 22:53:55 INFO Completed upload id=1 objects=3 duration=14.848333ms21602026/11/11 22:53:55 INFO Received uploads request method=POST path=/api/pending_closures21612026/11/11 22:53:55 INFO Received uploads request method=POST path=/api/pending_closures21622026/11/11 22:53:55 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst21632026/11/11 22:53:55 WARN Found objects in DB but missing from S3, will re-upload count=121642026/11/11 22:53:55 INFO Aborted multipart uploads count=0 kept=021652026/11/11 22:53:55 WARN Force mode enabled - objects will be deleted immediately without grace period21662026-11-11 22:53:55.810 UTC [69603] ERROR: canceling statement due to user request21672026-11-11 22:53:55.810 UTC [69603] STATEMENT: -- name: MarkStaleObjects :execrows2168 WITH RECURSIVE ct AS (2169 SELECT timezone('UTC', now()) AS now2170 ),2171 closure_reach AS (2172 -- Start with all closure keys2173 SELECT o.key, o.refs2174 FROM objects o2175 INNER JOIN closures c ON o.key = c.key2176 UNION2177 -- Recursively add all referenced objects2178 SELECT o.key, o.refs2179 FROM objects o2180 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2181 ),2182 reachable_objects AS (2183 SELECT DISTINCT key FROM closure_reach2184 ),2185 stale_objects AS (2186 SELECT o.key2187 FROM objects AS o, ct2188 WHERE2189 NOT EXISTS (2190 SELECT 12191 FROM reachable_objects ro2192 WHERE ro.key = o.key2193 )2194 AND NOT EXISTS (2195 SELECT 12196 FROM pending_objects AS po2197 WHERE po.key = o.key2198 )2199 AND o.deleted_at IS NULL -- Only mark fresh objects2200 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2201 FOR UPDATE2202 )2203 UPDATE objects2204 SET2205 deleted_at = ct.now,2206 first_deleted_at = COALESCE(first_deleted_at, ct.now)2207 FROM stale_objects, ct2208 WHERE objects.key = stale_objects.key2209 22102026/11/11 22:53:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2211--- PASS: TestGCEndsOnShutdown (0.05s)2212 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (7.50s)2213 --- PASS: TestGCEndsOnShutdown/before_the_run (7.87s)2214 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (7.29s)22152026/11/11 22:53:55 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LjI4ODIxODczLWYwY2MtNDEyMC1hZGU4LWFiZGE5NjhiNTA2OXgxNzk0NDM3NjM0MDI3MDEzMDAw parts=1022162026/11/11 22:53:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22172026/11/11 22:53:55 INFO Completed upload id=1 objects=3 duration=10.510166ms22182026/11/11 22:53:55 INFO Received uploads request method=POST path=/api/pending_closures22192026/11/11 22:53:55 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 127.0.0.1:19999: connect: connection refused"22202026/11/11 22:53:55 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22212026/11/11 22:53:56 WARN Request failed, retrying attempt=2 backoff=201.266307ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22222026/11/11 22:53:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22232026/11/11 22:53:56 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LjJjMjNiMjdkLWRmMjYtNDVjOC05NTcwLWZlYjg4ZjUwMGMzMngxNzk0NDM3NjM0MzQzMzcxMDAw parts=1022242026/11/11 22:53:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22252026/11/11 22:53:56 INFO Completed upload id=1 objects=3 duration=5.7485ms22262026/11/11 22:53:56 INFO Received uploads request method=POST path=/api/pending_closures22272026/11/11 22:53:56 WARN Request failed, retrying attempt=3 backoff=376.104466ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22282026/11/11 22:53:56 WARN Request failed, retrying attempt=4 backoff=841.25925ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2229--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2230 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (7.52s)2231 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (7.79s)22322026/11/11 22:53:57 WARN Request failed, retrying attempt=5 backoff=1.662350794s error="Get \"http://localhost:19999/api/cache-config\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22332026/11/11 22:53:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22342026/11/11 22:53:58 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LmU4NzQ0ZGIxLTVlOTItNDZlMy05ZWVjLWIzZjZkZTVkYTgwNXgxNzk0NDM3NjM1NTkzMTIxMDAw parts=1022352026/11/11 22:53:58 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22362026/11/11 22:53:58 INFO Completed upload id=2 objects=3 duration=1.787625ms22372026/11/11 22:53:58 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22382026/11/11 22:53:59 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22392026/11/11 22:53:59 INFO Received uploads request method=POST path=/api/pending_closures22402026/11/11 22:53:59 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22412026/11/11 22:53:59 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo22422026/11/11 22:53:59 INFO Received uploads request method=POST path=/api/pending_closures22432026/11/11 22:53:59 INFO Aborted multipart uploads count=0 kept=022442026/11/11 22:53:59 WARN Force mode enabled - objects will be deleted immediately without grace period22452026/11/11 22:53:59 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22462026/11/11 22:53:59 WARN Request failed, retrying attempt=2 backoff=203.424486ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22472026/11/11 22:53:59 WARN Request failed, retrying attempt=3 backoff=398.406522ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22482026/11/11 22:53:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22492026/11/11 22:53:59 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=022502026/11/11 22:53:59 INFO Vacuumed table table=pending_closures22512026/11/11 22:53:59 INFO Vacuumed table table=pending_objects22522026/11/11 22:53:59 INFO Vacuumed table table=multipart_uploads22532026/11/11 22:53:59 INFO Vacuumed table table=closures22542026/11/11 22:53:59 WARN Request failed, retrying attempt=4 backoff=793.178482ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22552026/11/11 22:53:59 INFO Vacuumed table table=objects22562026/11/11 22:54:00 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=YTczN2Q1MjAtOWYyMC00ZTY0LTgxY2YtNTgyYjcyNDE0Y2M2LmQ5NmQ5NmZhLTQxZDQtNGU0Yy05MTI4LTFmY2I2ZjZiODIzY3gxNzk0NDM3NjM2MjQyNzMwMDAw parts=1022572026/11/11 22:54:00 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22582026/11/11 22:54:00 INFO Completed upload id=2 objects=3 duration=1.563375ms22592026/11/11 22:54:00 INFO Received uploads request method=POST path=/api/pending_closures22602026/11/11 22:54:00 INFO Aborted multipart uploads count=0 kept=022612026/11/11 22:54:00 WARN Force mode enabled - objects will be deleted immediately without grace period22622026/11/11 22:54: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=022632026/11/11 22:54:00 INFO Vacuumed table table=pending_closures22642026/11/11 22:54:00 INFO Vacuumed table table=pending_objects22652026/11/11 22:54:00 INFO Vacuumed table table=multipart_uploads22662026/11/11 22:54:00 INFO Vacuumed table table=closures22672026/11/11 22:54:00 INFO Vacuumed table table=objects22682026/11/11 22:54:00 WARN Request failed, retrying attempt=5 backoff=1.522676703s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp 127.0.0.1:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2269--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2270 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (9.96s)2271 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (10.28s)22722026/11/11 22:54:01 INFO Received uploads request method=POST path=/api/pending_closures22732026/11/11 22:54:01 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22742026/11/11 22:54:01 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo2275--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.01s)2276 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (10.70s)2277 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (9.98s)2278 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (9.24s)2279 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (12.62s)2280 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (14.57s)2281=== NAME TestOrphanedObjectsGCStressTest2282 orphaned_objects_gc_test.go:503: Stress test completed successfully:2283 orphaned_objects_gc_test.go:504: - Active objects preserved: 202284 orphaned_objects_gc_test.go:505: - Objects deleted: 2102285 orphaned_objects_gc_test.go:506: - Total GC'd: 2102286--- PASS: TestOrphanedObjectsGCStressTest (40.17s)2287--- PASS: TestClientErrorHandling (0.00s)2288 --- PASS: TestClientErrorHandling/InvalidStorePath (7.93s)2289 --- PASS: TestClientErrorHandling/InvalidAuthToken (9.20s)2290 --- PASS: TestClientErrorHandling/ServerNotAvailable (12.90s)2291PASS2292{"timestamp":"2026-11-11T22:54:02.250577Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56113","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(9)"}2293{"timestamp":"2026-11-11T22:54:02.251439Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:56384","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}22942026-11-11 22:54:02.389 UTC [69122] LOG: received smart shutdown request22952026-11-11 22:54:02.389 UTC [69122] LOG: background worker "logical replication launcher" (PID 69132) exited with exit code 122962026-11-11 22:54:03.707 UTC [69127] LOG: checkpoint complete: wrote 11375 buffers (69.4%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 33 recycled; write=10.709 s, sync=0.686 s, total=11.533 s; sync files=36842, longest=0.001 s, average=0.001 s; distance=534470 kB, estimate=534470 kB; lsn=0/2285DA00, redo lsn=0/2217EA8022972026-11-11 22:54:03.708 UTC [69127] LOG: shutting down22982026-11-11 22:54:03.708 UTC [69127] LOG: checkpoint starting: shutdown immediate22992026-11-11 22:54:03.749 UTC [69127] LOG: checkpoint complete: wrote 924 buffers (5.6%), wrote 1 SLRU buffers; 0 WAL file(s) added, 0 removed, 0 recycled; write=0.025 s, sync=0.016 s, total=0.042 s; sync files=419, longest=0.001 s, average=0.001 s; distance=7035 kB, estimate=481727 kB; lsn=0/2285DA78, redo lsn=0/2285DA7823002026-11-11 22:54:03.756 UTC [69122] LOG: database system is shut down2301Running OIDC tests...2302=== RUN TestAudienceForIssuer2303=== PAUSE TestAudienceForIssuer2304=== RUN TestGlobMatch2305=== PAUSE TestGlobMatch2306=== RUN TestValidateToken_ValidToken2307=== PAUSE TestValidateToken_ValidToken2308=== RUN TestValidateToken_WrongAudience2309=== PAUSE TestValidateToken_WrongAudience2310=== RUN TestValidateToken_Expired2311=== PAUSE TestValidateToken_Expired2312=== RUN TestValidateToken_BoundClaimsMismatch2313=== PAUSE TestValidateToken_BoundClaimsMismatch2314=== RUN TestValidateToken_BoundSubjectMismatch2315=== PAUSE TestValidateToken_BoundSubjectMismatch2316=== RUN TestValidateToken_MultipleProviders2317=== PAUSE TestValidateToken_MultipleProviders2318=== RUN TestValidateToken_NoMatchingProvider2319=== PAUSE TestValidateToken_NoMatchingProvider2320=== RUN TestValidateToken_KubernetesServiceAccount2321=== PAUSE TestValidateToken_KubernetesServiceAccount2322=== RUN TestNewValidator_KubernetesRequiresCA2323=== PAUSE TestNewValidator_KubernetesRequiresCA2324=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2325=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2326=== RUN TestPins_ReservedForMatchingRule2327=== PAUSE TestPins_ReservedForMatchingRule2328=== RUN TestPins_TopLevelShorthand2329=== PAUSE TestPins_TopLevelShorthand2330=== RUN TestPins_ConfigValidation2331=== PAUSE TestPins_ConfigValidation2332=== RUN TestScopes_LegacyProviderDefaultsToWrite2333=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2334=== RUN TestScopes_Rules2335=== PAUSE TestScopes_Rules2336=== RUN TestScopes_ConfigValidation2337=== PAUSE TestScopes_ConfigValidation2338=== CONT TestAudienceForIssuer2339--- PASS: TestAudienceForIssuer (0.00s)2340=== CONT TestValidateToken_BoundSubjectMismatch2341=== CONT TestPins_ConfigValidation2342=== CONT TestValidateToken_BoundClaimsMismatch2343=== CONT TestValidateToken_NoMatchingProvider2344=== CONT TestValidateToken_MultipleProviders2345=== CONT TestValidateToken_Expired2346=== CONT TestValidateToken_WrongAudience2347=== CONT TestValidateToken_ValidToken2348=== CONT TestGlobMatch2349=== RUN TestGlobMatch/foo_foo2350=== PAUSE TestGlobMatch/foo_foo2351=== RUN TestGlobMatch/foo_bar2352=== PAUSE TestGlobMatch/foo_bar2353=== RUN TestGlobMatch/*_2354=== PAUSE TestGlobMatch/*_2355=== RUN TestGlobMatch/*_anything2356=== CONT TestScopes_Rules2357=== CONT TestScopes_ConfigValidation2358=== CONT TestPins_ReservedForMatchingRule2359=== CONT TestPins_TopLevelShorthand2360=== CONT TestScopes_LegacyProviderDefaultsToWrite2361=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2362=== CONT TestNewValidator_KubernetesRequiresCA2363=== CONT TestValidateToken_KubernetesServiceAccount2364--- PASS: TestPins_ConfigValidation (0.01s)2365--- PASS: TestScopes_ConfigValidation (0.00s)2366=== PAUSE TestGlobMatch/*_anything2367=== RUN TestGlobMatch/foo*_foo2368=== PAUSE TestGlobMatch/foo*_foo2369=== RUN TestGlobMatch/foo*_foobar2370=== PAUSE TestGlobMatch/foo*_foobar2371=== RUN TestGlobMatch/foo*_bar2372=== PAUSE TestGlobMatch/foo*_bar2373=== RUN TestGlobMatch/*bar_bar2374=== PAUSE TestGlobMatch/*bar_bar2375=== RUN TestGlobMatch/*bar_foobar2376=== PAUSE TestGlobMatch/*bar_foobar2377=== RUN TestGlobMatch/*bar_foo2378=== PAUSE TestGlobMatch/*bar_foo2379=== RUN TestGlobMatch/foo*bar_foobar2380=== PAUSE TestGlobMatch/foo*bar_foobar2381=== RUN TestGlobMatch/foo*bar_foo123bar2382=== PAUSE TestGlobMatch/foo*bar_foo123bar2383=== RUN TestGlobMatch/foo*bar_foobarbaz2384=== PAUSE TestGlobMatch/foo*bar_foobarbaz2385=== RUN TestGlobMatch/*/*_foo/bar2386=== PAUSE TestGlobMatch/*/*_foo/bar2387=== RUN TestGlobMatch/*/*_foo2388=== PAUSE TestGlobMatch/*/*_foo2389=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2390=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2391=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02392=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02393=== RUN TestGlobMatch/refs/*/main_refs/heads/main2394=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2395=== RUN TestGlobMatch/fo?_foo2396=== PAUSE TestGlobMatch/fo?_foo2397=== RUN TestGlobMatch/fo?_fo2398=== PAUSE TestGlobMatch/fo?_fo2399=== RUN TestGlobMatch/fo?_fooo2400=== PAUSE TestGlobMatch/fo?_fooo2401=== RUN TestGlobMatch/?oo_foo2402=== PAUSE TestGlobMatch/?oo_foo2403=== RUN TestGlobMatch/?oo_boo2404=== PAUSE TestGlobMatch/?oo_boo2405=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2406=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2407=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2408=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2409=== CONT TestGlobMatch/foo_foo2410=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2411=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2412=== CONT TestGlobMatch/?oo_boo2413=== CONT TestGlobMatch/?oo_foo2414=== CONT TestGlobMatch/fo?_fooo2415=== CONT TestGlobMatch/fo?_fo2416=== CONT TestGlobMatch/fo?_foo2417=== CONT TestGlobMatch/refs/*/main_refs/heads/main2418=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02419=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2420=== CONT TestGlobMatch/*/*_foo2421=== CONT TestGlobMatch/*/*_foo/bar2422=== CONT TestGlobMatch/foo*bar_foobarbaz2423=== CONT TestGlobMatch/foo*bar_foo123bar2424=== CONT TestGlobMatch/foo*bar_foobar2425=== CONT TestGlobMatch/*bar_foo2426=== CONT TestGlobMatch/*bar_foobar2427=== CONT TestGlobMatch/*bar_bar2428=== CONT TestGlobMatch/foo*_bar2429=== CONT TestGlobMatch/foo*_foobar2430=== CONT TestGlobMatch/foo*_foo2431=== CONT TestGlobMatch/*_anything2432=== CONT TestGlobMatch/*_2433=== CONT TestGlobMatch/foo_bar2434--- PASS: TestGlobMatch (0.01s)2435 --- PASS: TestGlobMatch/foo_foo (0.00s)2436 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2437 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2438 --- PASS: TestGlobMatch/?oo_boo (0.00s)2439 --- PASS: TestGlobMatch/?oo_foo (0.00s)2440 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2441 --- PASS: TestGlobMatch/fo?_fo (0.00s)2442 --- PASS: TestGlobMatch/fo?_foo (0.00s)2443 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2444 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2445 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2446 --- PASS: TestGlobMatch/*/*_foo (0.00s)2447 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2448 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2449 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2450 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2451 --- PASS: TestGlobMatch/*bar_foo (0.00s)2452 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2453 --- PASS: TestGlobMatch/*bar_bar (0.00s)2454 --- PASS: TestGlobMatch/foo*_bar (0.00s)2455 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2456 --- PASS: TestGlobMatch/foo*_foo (0.00s)2457 --- PASS: TestGlobMatch/*_anything (0.00s)2458 --- PASS: TestGlobMatch/*_ (0.00s)2459 --- PASS: TestGlobMatch/foo_bar (0.00s)24602026/11/11 22:54:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56432/oidc2461--- PASS: TestPins_ReservedForMatchingRule (0.05s)24622026/11/11 22:54:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56434/oidc2463--- PASS: TestScopes_Rules (0.05s)24642026/11/11 22:54:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56436/oidc24652026/11/11 22:54:05 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:564382466--- PASS: TestValidateToken_BoundClaimsMismatch (0.07s)24672026/11/11 22:54:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56440/oidc2468--- PASS: TestValidateToken_KubernetesServiceAccount (0.07s)2469--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.07s)24702026/11/11 22:54:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56443/oidc2471--- PASS: TestValidateToken_Expired (0.08s)24722026/11/11 22:54:05 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324732026/11/11 22:54:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56447/oidc2474--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.08s)2475--- PASS: TestValidateToken_ValidToken (0.08s)24762026/11/11 22:54:05 http: TLS handshake error from 127.0.0.1:56451: read tcp 127.0.0.1:56450->127.0.0.1:56451: use of closed network connection2477--- PASS: TestNewValidator_KubernetesRequiresCA (0.09s)24782026/11/11 22:54:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56452/oidc2479--- PASS: TestValidateToken_BoundSubjectMismatch (0.11s)24802026/11/11 22:54:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56454/oidc2481--- PASS: TestValidateToken_WrongAudience (0.12s)24822026/11/11 22:54:05 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:56458/oidc2483--- PASS: TestPins_TopLevelShorthand (0.18s)24842026/11/11 22:54:05 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56456/oidc24852026/11/11 22:54:05 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:56460/oidc2486--- PASS: TestValidateToken_MultipleProviders (0.20s)24872026/11/11 22:54:05 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:56457/oidc2488--- PASS: TestValidateToken_NoMatchingProvider (0.24s)2489PASS2490Running hook tests...2491=== RUN TestSendPathsEmpty2492=== PAUSE TestSendPathsEmpty2493=== RUN TestQueueEnqueueAndFetch2494=== PAUSE TestQueueEnqueueAndFetch2495=== RUN TestQueueDeduplication2496=== PAUSE TestQueueDeduplication2497=== RUN TestQueueRemove2498=== PAUSE TestQueueRemove2499=== RUN TestQueueFetchBatchLimit2500=== PAUSE TestQueueFetchBatchLimit2501=== RUN TestQueueRetryMovesToBack2502=== PAUSE TestQueueRetryMovesToBack2503=== RUN TestQueueFetchRemoveLifecycle2504=== PAUSE TestQueueFetchRemoveLifecycle2505=== RUN TestQueueConcurrentWriters2506=== PAUSE TestQueueConcurrentWriters2507=== RUN TestQueueRemoveLargeClosure2508=== PAUSE TestQueueRemoveLargeClosure2509=== RUN TestServerClientIntegration2510--- PASS: TestServerClientIntegration (0.00s)2511=== RUN TestServerQueueError25122026/11/11 22:54:06 ERROR Failed to queue paths error="permission denied" count=12513--- PASS: TestServerQueueError (0.00s)2514=== RUN TestGetListenerSocketActivation2515 server_test.go:145: systemd socket activation does not exist on darwin2516--- SKIP: TestGetListenerSocketActivation (0.00s)2517=== RUN TestServerStalledClientDoesNotBlockShutdown2518=== PAUSE TestServerStalledClientDoesNotBlockShutdown2519=== RUN TestServerBacksOffOnAcceptErrors2520=== PAUSE TestServerBacksOffOnAcceptErrors2521=== RUN TestDrainIsolatesPoisonPath2522=== PAUSE TestDrainIsolatesPoisonPath2523=== RUN TestRunNotBlockedByPoisonHead2524=== PAUSE TestRunNotBlockedByPoisonHead2525=== RUN TestDrainGivesUpWhenServerDown2526=== PAUSE TestDrainGivesUpWhenServerDown2527=== RUN TestFailedPathPrunedByLaterClosure2528=== PAUSE TestFailedPathPrunedByLaterClosure2529=== RUN TestWorkerUploadsAndRemoves2530=== PAUSE TestWorkerUploadsAndRemoves2531=== RUN TestWorkerSkipsGCdPaths2532=== PAUSE TestWorkerSkipsGCdPaths2533=== RUN TestWorkerPrunesClosureDeps2534=== PAUSE TestWorkerPrunesClosureDeps2535=== RUN TestDrainTimeout2536=== PAUSE TestDrainTimeout2537=== RUN TestWorkerRemoveFailureIsNotProgress2538=== PAUSE TestWorkerRemoveFailureIsNotProgress2539=== RUN TestWorkerKeepsPathItCannotStat2540=== PAUSE TestWorkerKeepsPathItCannotStat2541=== CONT TestSendPathsEmpty2542=== CONT TestWorkerKeepsPathItCannotStat2543--- PASS: TestSendPathsEmpty (0.00s)2544=== CONT TestDrainIsolatesPoisonPath2545=== CONT TestServerBacksOffOnAcceptErrors2546=== CONT TestServerStalledClientDoesNotBlockShutdown25472026/11/11 22:54:06 ERROR Accept failed error="too many open files"2548=== CONT TestQueueRemoveLargeClosure2549=== CONT TestQueueConcurrentWriters2550=== CONT TestQueueFetchRemoveLifecycle2551=== CONT TestQueueRetryMovesToBack2552=== CONT TestWorkerSkipsGCdPaths2553=== CONT TestQueueFetchBatchLimit2554=== CONT TestWorkerRemoveFailureIsNotProgress2555=== CONT TestDrainTimeout2556=== CONT TestQueueRemove2557=== CONT TestWorkerPrunesClosureDeps2558=== CONT TestQueueDeduplication2559=== CONT TestFailedPathPrunedByLaterClosure2560=== CONT TestQueueEnqueueAndFetch2561=== CONT TestWorkerUploadsAndRemoves2562=== CONT TestDrainGivesUpWhenServerDown2563=== CONT TestRunNotBlockedByPoisonHead25642026/11/11 22:54:06 ERROR Accept failed error="too many open files"25652026/11/11 22:54:06 INFO Uploading batch count=22566--- PASS: TestQueueDeduplication (0.01s)25672026/11/11 22:54:06 INFO Upload queue status pending=225682026/11/11 22:54:06 INFO Uploading batch count=225692026/11/11 22:54:06 INFO Upload queue status pending=225702026/11/11 22:54:06 INFO Uploading batch count=125712026/11/11 22:54:06 ERROR Upload failed error="upload failed" count=125722026/11/11 22:54:06 INFO Uploading batch count=12573--- PASS: TestQueueEnqueueAndFetch (0.01s)25742026/11/11 22:54:06 INFO Uploading batch count=425752026/11/11 22:54:06 ERROR Upload failed error="upload failed" count=425762026/11/11 22:54:06 INFO Upload queue status pending=32577--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25782026/11/11 22:54:06 INFO Uploading batch count=125792026/11/11 22:54:06 INFO Uploading batch count=225802026/11/11 22:54:06 ERROR Upload failed error="upload failed" count=225812026/11/11 22:54:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestDrainGivesUpWhenServerDown3470304406/002/a25822026/11/11 22:54:06 INFO Upload queue status pending=225832026/11/11 22:54:06 INFO Uploading batch count=125842026/11/11 22:54:06 ERROR Upload failed error="upload failed" count=125852026/11/11 22:54:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestWorkerSkipsGCdPaths2386599163/002/nonexistent25862026/11/11 22:54:06 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestWorkerKeepsPathItCannotStat4276863091/002/locked/aaa error="stat /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestWorkerKeepsPathItCannotStat4276863091/002/locked/aaa: permission denied"25872026/11/11 22:54:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestDrainGivesUpWhenServerDown3470304406/002/b25882026/11/11 22:54:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestDrainIsolatesPoisonPath373337501/002/bbb2589--- PASS: TestQueueFetchBatchLimit (0.01s)25902026/11/11 22:54:06 INFO Uploading batch count=125912026/11/11 22:54:06 ERROR Accept failed error="too many open files"2592--- PASS: TestQueueRemove (0.02s)25932026/11/11 22:54:06 INFO Uploading batch count=125942026/11/11 22:54:06 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestWorkerKeepsPathItCannotStat4276863091/002/locked/aaa error="stat /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestWorkerKeepsPathItCannotStat4276863091/002/locked/aaa: permission denied"25952026/11/11 22:54:06 INFO Uploading batch count=225962026/11/11 22:54:06 ERROR Upload failed error="upload failed" count=225972026/11/11 22:54:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestWorkerRemoveFailureIsNotProgress3416757613/002/nonexistent25982026/11/11 22:54:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestDrainGivesUpWhenServerDown3470304406/002/c25992026/11/11 22:54:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126002026/11/11 22:54:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestWorkerRemoveFailureIsNotProgress3416757613/002/nonexistent26012026/11/11 22:54:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126022026/11/11 22:54:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestDrainGivesUpWhenServerDown3470304406/002/d26032026/11/11 22:54:06 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestWorkerRemoveFailureIsNotProgress3416757613/002/nonexistent26042026/11/11 22:54:06 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126052026/11/11 22:54:06 INFO Uploading batch count=126062026/11/11 22:54:06 ERROR Upload failed error="upload failed" count=126072026/11/11 22:54:06 WARN Cannot stat store path, will retry later path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestWorkerKeepsPathItCannotStat4276863091/002/locked/aaa error="stat /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestWorkerKeepsPathItCannotStat4276863091/002/locked/aaa: permission denied"26082026/11/11 22:54:06 ERROR Drain finished with paths left in queue remaining=12609--- PASS: TestQueueRetryMovesToBack (0.02s)26102026/11/11 22:54:06 INFO Uploading batch count=126112026/11/11 22:54:06 ERROR Upload failed error="upload failed" count=126122026/11/11 22:54:06 ERROR Drain finished with paths left in queue remaining=126132026/11/11 22:54:06 INFO Uploading batch count=226142026/11/11 22:54:06 ERROR Upload failed error="upload failed" count=226152026/11/11 22:54:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestDrainGivesUpWhenServerDown3470304406/002/e26162026/11/11 22:54:06 INFO Uploading batch count=126172026/11/11 22:54:06 ERROR Upload failed error="upload failed" count=126182026/11/11 22:54:06 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestDrainGivesUpWhenServerDown3470304406/002/f26192026/11/11 22:54:06 ERROR Drain finished with paths left in queue remaining=126202026/11/11 22:54:06 ERROR Drain finished with paths left in queue remaining=102621--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2622--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)2623--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2624--- PASS: TestDrainIsolatesPoisonPath (0.02s)2625--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2626--- PASS: TestWorkerUploadsAndRemoves (0.03s)2627--- PASS: TestWorkerPrunesClosureDeps (0.03s)2628--- PASS: TestWorkerSkipsGCdPaths (0.03s)26292026/11/11 22:54:06 ERROR Accept failed error="too many open files"2630--- PASS: TestQueueRemoveLargeClosure (0.05s)2631--- PASS: TestQueueConcurrentWriters (0.06s)26322026/11/11 22:54:06 ERROR Accept failed error="too many open files"26332026/11/11 22:54:06 ERROR Accept failed error="too many open files"26342026/11/11 22:54:06 ERROR Failed to decode request error="read unix /private/var/tb/5/scratch/2ea555b3b60ac49d/build/hook1749624426/test.sock->: i/o timeout"26352026/11/11 22:54:06 ERROR Failed to write response error="write unix /private/var/tb/5/scratch/2ea555b3b60ac49d/build/hook1749624426/test.sock->: i/o timeout"2636--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26372026/11/11 22:54:06 ERROR Upload failed error="context deadline exceeded" count=226382026/11/11 22:54:06 ERROR Drain finished with paths left in queue remaining=42639--- PASS: TestDrainTimeout (0.21s)26402026/11/11 22:54:06 ERROR Accept failed error="too many open files"26412026/11/11 22:54:06 ERROR Accept failed error="too many open files"2642--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26432026/11/11 22:54:07 INFO Uploading batch count=126442026/11/11 22:54:07 INFO Uploading batch count=126452026/11/11 22:54:07 INFO Uploading batch count=126462026/11/11 22:54:07 ERROR Upload failed error="upload failed" count=126472026/11/11 22:54:07 INFO Uploading batch count=126482026/11/11 22:54:07 ERROR Upload failed error="upload failed" count=126492026/11/11 22:54:07 INFO Uploading batch count=126502026/11/11 22:54:07 ERROR Upload failed error="upload failed" count=126512026/11/11 22:54:07 INFO Uploading batch count=126522026/11/11 22:54:07 ERROR Upload failed error="upload failed" count=126532026/11/11 22:54:07 ERROR Drain finished with paths left in queue remaining=12654--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2655PASS2656Running signing tests...2657=== RUN TestExternalSigner2658=== PAUSE TestExternalSigner2659=== RUN TestExternalSignerWrongPublicKey2660=== PAUSE TestExternalSignerWrongPublicKey2661=== RUN TestExternalSignerErrors2662=== PAUSE TestExternalSignerErrors2663=== RUN TestExternalSignerRestartsAfterCrash2664=== PAUSE TestExternalSignerRestartsAfterCrash2665=== RUN TestExternalSignerProgramErrorKeepsProcess2666=== PAUSE TestExternalSignerProgramErrorKeepsProcess2667=== RUN TestExternalSignerClose2668=== PAUSE TestExternalSignerClose2669=== RUN TestExternalSignerRejectsInvalidPublicKey2670=== PAUSE TestExternalSignerRejectsInvalidPublicKey2671=== RUN TestExternalSignerCancellation2672=== PAUSE TestExternalSignerCancellation2673=== RUN TestGenerateFingerprint2674=== PAUSE TestGenerateFingerprint2675=== RUN TestParseSigningKey2676=== PAUSE TestParseSigningKey2677=== RUN TestSign2678=== PAUSE TestSign2679=== RUN TestSignBatch2680=== PAUSE TestSignBatch2681=== RUN TestNilKeyPublicKey2682=== PAUSE TestNilKeyPublicKey2683=== RUN TestSignErrors2684=== PAUSE TestSignErrors2685=== CONT TestExternalSigner2686=== CONT TestExternalSignerProgramErrorKeepsProcess2687=== CONT TestExternalSignerCancellation2688=== CONT TestExternalSignerErrors2689=== RUN TestExternalSignerErrors/exit_on_request2690=== PAUSE TestExternalSignerErrors/exit_on_request2691=== CONT TestSignErrors2692=== CONT TestNilKeyPublicKey2693--- PASS: TestNilKeyPublicKey (0.00s)2694=== CONT TestSignBatch2695=== CONT TestSign2696=== CONT TestParseSigningKey2697=== RUN TestParseSigningKey/valid_32-byte_key2698=== PAUSE TestParseSigningKey/valid_32-byte_key2699=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2700=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2701=== RUN TestParseSigningKey/no_colon2702=== PAUSE TestParseSigningKey/no_colon2703=== RUN TestParseSigningKey/empty_name2704=== CONT TestGenerateFingerprint2705=== RUN TestGenerateFingerprint/basic_with_references2706=== PAUSE TestGenerateFingerprint/basic_with_references2707=== CONT TestExternalSignerRestartsAfterCrash2708=== CONT TestExternalSignerWrongPublicKey2709=== CONT TestExternalSignerRejectsInvalidPublicKey2710=== RUN TestExternalSignerRejectsInvalidPublicKey/#002711=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002712=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2713=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2714=== CONT TestExternalSignerClose2715=== RUN TestExternalSignerErrors/wrong_id2716=== PAUSE TestParseSigningKey/empty_name2717=== RUN TestParseSigningKey/invalid_base642718=== RUN TestGenerateFingerprint/no_references2719=== PAUSE TestExternalSignerErrors/wrong_id2720=== PAUSE TestGenerateFingerprint/no_references2721=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2722=== PAUSE TestParseSigningKey/invalid_base642723=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2724=== RUN TestExternalSignerErrors/missing_signatures2725=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2726=== PAUSE TestExternalSignerErrors/missing_signatures2727=== RUN TestExternalSignerErrors/null_signatures2728=== PAUSE TestExternalSignerErrors/null_signatures2729=== RUN TestExternalSignerErrors/too_few_signatures2730=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2731=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2732=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2733=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2734=== RUN TestGenerateFingerprint/invalid_nar_hash_length2735=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2736=== RUN TestGenerateFingerprint/invalid_store_path_prefix2737=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2738=== RUN TestGenerateFingerprint/invalid_reference_prefix2739=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2740=== CONT TestGenerateFingerprint/basic_with_references2741=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2742=== PAUSE TestExternalSignerErrors/too_few_signatures2743=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2744=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2745=== CONT TestGenerateFingerprint/invalid_nar_hash_length2746=== CONT TestGenerateFingerprint/invalid_reference_prefix2747=== CONT TestGenerateFingerprint/invalid_store_path_prefix2748=== RUN TestParseSigningKey/wrong_length2749=== PAUSE TestParseSigningKey/wrong_length2750=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2751=== CONT TestParseSigningKey/empty_name2752=== CONT TestParseSigningKey/no_colon2753=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2754=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2755=== CONT TestGenerateFingerprint/no_references2756--- PASS: TestGenerateFingerprint (0.00s)2757 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2758 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2759 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2760 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2761 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2762 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2763 --- PASS: TestGenerateFingerprint/no_references (0.00s)2764=== RUN TestExternalSignerErrors/unrequested_key2765=== PAUSE TestExternalSignerErrors/unrequested_key2766=== RUN TestExternalSignerErrors/missing_signature_name2767=== PAUSE TestExternalSignerErrors/missing_signature_name2768=== RUN TestExternalSignerErrors/invalid_JSON2769=== PAUSE TestExternalSignerErrors/invalid_JSON2770=== RUN TestExternalSignerErrors/wrong_shape2771=== PAUSE TestExternalSignerErrors/wrong_shape2772=== RUN TestExternalSignerErrors/wrong_signatures_shape2773=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2774=== RUN TestExternalSignerErrors/wrong_signature_name2775=== PAUSE TestExternalSignerErrors/wrong_signature_name2776=== RUN TestExternalSignerErrors/invalid_signature_base642777=== RUN TestSignErrors/nil_key2778=== PAUSE TestSignErrors/nil_key2779=== PAUSE TestExternalSignerErrors/invalid_signature_base642780=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2781=== RUN TestExternalSignerErrors/program_error2782=== PAUSE TestExternalSignerErrors/program_error2783=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2784=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2785=== CONT TestParseSigningKey/valid_32-byte_key2786=== CONT TestParseSigningKey/wrong_length2787=== CONT TestParseSigningKey/invalid_base642788=== CONT TestExternalSignerRejectsInvalidPublicKey/#002789=== RUN TestSignErrors/nil_narinfo2790=== PAUSE TestSignErrors/nil_narinfo2791=== RUN TestSignErrors/invalid_narinfo2792--- PASS: TestSign (0.00s)2793=== RUN TestExternalSignerErrors/null2794=== PAUSE TestSignErrors/invalid_narinfo2795=== RUN TestSignErrors/canceled2796=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2797=== PAUSE TestExternalSignerErrors/null2798=== PAUSE TestSignErrors/canceled2799=== RUN TestExternalSignerErrors/wrong_signature_length2800=== PAUSE TestExternalSignerErrors/wrong_signature_length2801=== RUN TestExternalSignerErrors/exit_at_startup2802--- PASS: TestParseSigningKey (0.00s)2803 --- PASS: TestParseSigningKey/empty_name (0.00s)2804 --- PASS: TestParseSigningKey/no_colon (0.00s)2805 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2806 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2807 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2808 --- PASS: TestParseSigningKey/wrong_length (0.00s)2809--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2810 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2811 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2812 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2813 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2814 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2815=== CONT TestSignErrors/nil_key2816=== PAUSE TestExternalSignerErrors/exit_at_startup2817=== CONT TestExternalSignerErrors/exit_on_request2818=== CONT TestExternalSignerErrors/wrong_signatures_shape2819=== CONT TestExternalSignerErrors/null2820=== CONT TestExternalSignerErrors/exit_at_startup2821=== CONT TestExternalSignerErrors/null_signatures2822=== CONT TestExternalSignerErrors/wrong_signature_length2823=== CONT TestExternalSignerErrors/wrong_id2824=== CONT TestSignErrors/canceled2825=== CONT TestSignErrors/invalid_narinfo2826=== CONT TestSignErrors/nil_narinfo2827=== CONT TestExternalSignerErrors/unrequested_key2828=== CONT TestExternalSignerErrors/too_few_signatures2829=== CONT TestExternalSignerErrors/wrong_shape2830=== CONT TestExternalSignerErrors/invalid_signature_base642831--- PASS: TestSignBatch (0.00s)2832=== CONT TestExternalSignerErrors/missing_signature_name2833=== CONT TestExternalSignerErrors/program_error2834=== CONT TestExternalSignerErrors/missing_signatures2835=== CONT TestExternalSignerErrors/invalid_JSON2836=== CONT TestExternalSignerErrors/wrong_signature_name2837--- PASS: TestSignErrors (0.00s)2838 --- PASS: TestSignErrors/nil_key (0.00s)2839 --- PASS: TestSignErrors/canceled (0.00s)2840 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2841 --- PASS: TestSignErrors/nil_narinfo (0.00s)2842--- PASS: TestExternalSigner (0.23s)2843--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.40s)2844--- PASS: TestExternalSignerClose (0.59s)2845--- PASS: TestExternalSignerCancellation (0.80s)2846--- PASS: TestExternalSignerRestartsAfterCrash (0.97s)2847/private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestExternalSignerRestartsAfterCrash1239690467/001/sign program: line 7: /private/var/tb/5/scratch/2ea555b3b60ac49d/build/TestExternalSignerRestartsAfterCrash1239690467/001/sign program.starts: No such file or directory2848--- PASS: TestExternalSignerWrongPublicKey (1.14s)2849--- PASS: TestExternalSignerErrors (0.00s)2850 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.33s)2851 --- PASS: TestExternalSignerErrors/unrequested_key (1.51s)2852 --- PASS: TestExternalSignerErrors/wrong_id (1.70s)2853 --- PASS: TestExternalSignerErrors/exit_on_request (1.88s)2854 --- PASS: TestExternalSignerErrors/wrong_signature_name (2.07s)2855 --- PASS: TestExternalSignerErrors/too_few_signatures (2.26s)2856 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (2.44s)2857 --- PASS: TestExternalSignerErrors/exit_at_startup (2.64s)2858 --- PASS: TestExternalSignerErrors/missing_signatures (2.82s)2859 --- PASS: TestExternalSignerErrors/wrong_shape (3.01s)2860 --- PASS: TestExternalSignerErrors/invalid_JSON (3.20s)2861 --- PASS: TestExternalSignerErrors/program_error (3.39s)2862 --- PASS: TestExternalSignerErrors/missing_signature_name (3.57s)2863 --- PASS: TestExternalSignerErrors/null (3.76s)2864 --- PASS: TestExternalSignerErrors/null_signatures (3.94s)2865 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (4.13s)2866PASS2867Running OpenBao signer tests...2868=== RUN TestSign2869=== PAUSE TestSign2870=== RUN TestSignErrors2871=== PAUSE TestSignErrors2872=== RUN TestServe2873=== PAUSE TestServe2874=== RUN TestServeRejectsGarbage2875=== PAUSE TestServeRejectsGarbage2876=== CONT TestSign2877=== CONT TestServeRejectsGarbage2878=== CONT TestSignErrors2879=== CONT TestServe2880=== RUN TestSignErrors/http_error2881--- PASS: TestServeRejectsGarbage (0.00s)2882=== PAUSE TestSignErrors/http_error2883=== RUN TestSignErrors/invalid_json2884=== PAUSE TestSignErrors/invalid_json2885=== RUN TestSignErrors/no_prefix2886=== PAUSE TestSignErrors/no_prefix2887=== RUN TestSignErrors/invalid_base642888=== PAUSE TestSignErrors/invalid_base642889=== CONT TestSignErrors/http_error2890=== CONT TestSignErrors/no_prefix2891=== CONT TestSignErrors/invalid_json2892=== CONT TestSignErrors/invalid_base642893--- PASS: TestServe (0.00s)2894--- PASS: TestSign (0.00s)2895--- PASS: TestSignErrors (0.00s)2896 --- PASS: TestSignErrors/invalid_base64 (0.00s)2897 --- PASS: TestSignErrors/no_prefix (0.00s)2898 --- PASS: TestSignErrors/http_error (0.00s)2899 --- PASS: TestSignErrors/invalid_json (0.00s)2900PASS