niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #458
· 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_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (6.63s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestDoWithRetry_BodyReplayedViaGetBody117=== CONT TestDumpPathWriterError118=== CONT TestResolveStorePath119=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer120=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1212026/11/03 08:15:45 WARN Rate limiter enabled after throttle name=server-test rate=5122=== CONT TestRateLimiterFeedback123=== CONT TestPathInfoCACompatibility124=== RUN TestPathInfoCACompatibility/null_ca_field125=== PAUSE TestPathInfoCACompatibility/null_ca_field126=== RUN TestPathInfoCACompatibility/old_string_format_-_text127=== CONT TestParsePathInfoJSONMultiplePaths128=== CONT TestParsePathInfoJSON129=== CONT TestPathInfoHashCompatibility130=== CONT TestGetStorePathHash131=== CONT TestConvertHashToNix32132=== CONT TestEncodeNixBase32WithRealHash133=== CONT TestEncodeNixBase32134=== CONT TestSetClientTLS135=== CONT TestScriptTokenEmptyCommand136=== CONT TestScriptTokenScriptFails137=== CONT TestScriptTokenBadJSON138=== CONT TestScriptTokenEmptyToken139=== CONT TestScriptTokenCachesUntilRefresh140=== CONT TestScriptTokenNoExpiryRerunsEveryCall141=== CONT TestFileTokenEmpty142=== CONT TestFileTokenMissing143=== RUN TestRateLimiterFeedback/429_enables_limiter144=== RUN TestGetStorePathHash/valid_store_path145=== PAUSE TestGetStorePathHash/valid_store_path146=== RUN TestGetStorePathHash/basename_without_hyphen_should_error147=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error148=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error149=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error150=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error151=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error152=== CONT TestSetClientTLSErrors153=== CONT TestSetClientTLSDoesNotMutateDefaultTransport154=== CONT TestStaticToken155--- PASS: TestEncodeNixBase32WithRealHash (0.00s)156=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text157=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths158=== RUN TestParsePathInfoJSON/Nix_format159=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)160=== RUN TestEncodeNixBase32/test_string_hash161=== RUN TestConvertHashToNix32/SRI_format_to_Nix32162=== CONT TestFileTokenReadsAndCaches163=== CONT TestStreamPushIsolatesFailures164=== PAUSE TestRateLimiterFeedback/429_enables_limiter165=== RUN TestRateLimiterFeedback/503_enables_limiter166=== PAUSE TestRateLimiterFeedback/503_enables_limiter167=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter168=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter169=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter170=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter171=== CONT TestClientSignaturesByStorePath172=== CONT TestStreamPushReportsSkippedPaths173=== CONT TestStreamPushReportsSignatures174--- PASS: TestResolveStorePath (0.00s)175--- PASS: TestFileTokenMissing (0.00s)176--- PASS: TestScriptTokenEmptyCommand (0.00s)177--- PASS: TestStaticToken (0.00s)178--- PASS: TestClientSignaturesByStorePath (0.00s)179--- PASS: TestStreamPushReportsSkippedPaths (0.00s)1802026/11/03 08:15:45 ERROR Upload failed error="bad path" count=3181--- PASS: TestStreamPushIsolatesFailures (0.00s)182=== CONT TestStreamPushRequestLine183--- PASS: TestFileTokenEmpty (0.00s)184=== CONT TestStreamPushGivesUpOnDeadServer1852026/11/03 08:15:45 ERROR Upload failed error="connection refused" count=201862026/11/03 08:15:45 ERROR Server seems unavailable, giving up on batch untried=17187--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)188=== CONT TestShellSplitErrors189--- PASS: TestShellSplitErrors (0.00s)190=== CONT TestStreamPushBatchesUnderLoad191=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false192=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false193=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true194=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true195=== CONT TestStreamPushReportsEveryPath196--- PASS: TestStreamPushReportsEveryPath (0.00s)197=== CONT TestUploadMultipart_PartsInParallel198=== CONT TestStreamPushStopsWhenCanceled199=== PAUSE TestParsePathInfoJSON/Nix_format200=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)201=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths202=== RUN TestParsePathInfoJSON/Lix_format203=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon204=== CONT TestDumpPathSingleFile205--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)206--- PASS: TestFileTokenReadsAndCaches (0.00s)207--- PASS: TestStreamPushStopsWhenCanceled (0.01s)208=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths209=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive210=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive211=== RUN TestPathInfoCACompatibility/new_structured_format_-_text212=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text213=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method2142026/11/03 08:15:45 WARN Rate limiter enabled after throttle name=server-test rate=52152026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:50001216=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method217=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths218=== RUN TestSetClientTLS/rejects_connection_without_client_cert219=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert220=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA221=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon222=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI223=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI224=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512225=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512226=== CONT TestUploadMultipart_SupersededByPeer227=== RUN TestUploadMultipart_SupersededByPeer/exists228=== PAUSE TestUploadMultipart_SupersededByPeer/exists229=== RUN TestUploadMultipart_SupersededByPeer/missing230=== PAUSE TestUploadMultipart_SupersededByPeer/missing231=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA232=== CONT TestDoWithRetry_FinalResponseBodyReadable233=== RUN TestSetClientTLS/preserves_debug_logging_transport2342026/11/03 08:15:45 ERROR Upload failed error=boom count=1235=== PAUSE TestSetClientTLS/preserves_debug_logging_transport236=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32237=== RUN TestConvertHashToNix32/already_Nix32_format238=== PAUSE TestConvertHashToNix32/already_Nix32_format239=== RUN TestConvertHashToNix32/invalid_format240=== PAUSE TestConvertHashToNix32/invalid_format241=== CONT TestShellSplit2422026/11/03 08:15:45 WARN Rate limiter backed off name=server-test rate=5243=== CONT TestPartSizeForNAR244=== RUN TestPartSizeForNAR/zero_stays_at_minimum245=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum246=== RUN TestPartSizeForNAR/small_stays_at_minimum2472026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:50001248=== PAUSE TestPartSizeForNAR/small_stays_at_minimum249=== PAUSE TestParsePathInfoJSON/Lix_format250=== CONT TestSupersededNARStillUploadsListing2512026/11/03 08:15:45 ERROR Upload failed error=boom count=1252=== RUN TestSupersededNARStillUploadsListing/small_NAR253=== PAUSE TestSupersededNARStillUploadsListing/small_NAR254=== RUN TestSupersededNARStillUploadsListing/dump_cut_short255=== RUN TestParsePathInfoJSON/empty_input256=== PAUSE TestEncodeNixBase32/test_string_hash257--- PASS: TestShellSplit (0.00s)258--- PASS: TestStreamPushReportsSignatures (0.01s)259=== RUN TestEncodeNixBase32/empty_input260=== PAUSE TestEncodeNixBase32/empty_input261=== PAUSE TestParsePathInfoJSON/empty_input262=== CONT TestCaseHackSuffix263=== RUN TestParsePathInfoJSON/whitespace_only264=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun265=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum266=== CONT TestUploadMultipart_FailedPartBufferNotReused267=== CONT TestFilterOversizedClosures268=== RUN TestFilterOversizedClosures/no_limit_keeps_everything269=== RUN TestSetClientTLSErrors/missing_cert_file270=== PAUSE TestSetClientTLSErrors/missing_cert_file271=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything272=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short273=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails274=== CONT TestRetryTimeoutOutlastsMaxRetries275=== PAUSE TestParsePathInfoJSON/whitespace_only276=== RUN TestParsePathInfoJSON/invalid_JSON277=== CONT TestDumpPathMatchesNix278=== PAUSE TestParsePathInfoJSON/invalid_JSON279=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry280--- PASS: TestDoServerRequestAttachesToken (0.02s)281=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum282=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts283=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts284=== RUN TestPartSizeForNAR/1_TiB285=== PAUSE TestPartSizeForNAR/1_TiB286=== CONT TestRegisterUploadedObjectReusesConnections287=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica288=== RUN TestSetClientTLSErrors/missing_key_file2892026/11/03 08:15:45 INFO Garbage collection started2902026/11/03 08:15:45 WARN Rate limiter enabled after throttle name=s3-test rate=5291=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails292=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error293=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error294=== CONT TestGetStorePathHash/basename_without_hyphen_should_error295=== CONT TestRateLimiterFeedback/429_enables_limiter296=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped297=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped298=== RUN TestFilterOversizedClosures/all_closures_skipped299=== PAUSE TestFilterOversizedClosures/all_closures_skipped300=== CONT TestGetStorePathHash/valid_store_path301=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true302--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)303--- PASS: TestScriptTokenScriptFails (0.05s)304--- PASS: TestGetStorePathHash (0.00s)305 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)306 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)307 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)308 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)309=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false310=== RUN TestPartSizeForNAR/5_TiB_S3_max_object311=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object312=== RUN TestPartSizeForNAR/capped_at_5_GiB313=== PAUSE TestPartSizeForNAR/capped_at_5_GiB314=== PAUSE TestSetClientTLSErrors/missing_key_file315=== RUN TestSetClientTLSErrors/missing_ca_file316=== PAUSE TestSetClientTLSErrors/missing_ca_file317=== RUN TestSetClientTLSErrors/invalid_ca_file318=== PAUSE TestSetClientTLSErrors/invalid_ca_file319=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter320--- PASS: TestStreamPushBatchesUnderLoad (0.00s)321 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)322 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)323=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter324=== CONT TestRateLimiterFeedback/503_enables_limiter325=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths326=== CONT TestPathInfoCACompatibility/null_ca_field327=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method328=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths329--- PASS: TestParsePathInfoJSONMultiplePaths (0.01s)330 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)331 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)332=== CONT TestPathInfoCACompatibility/new_structured_format_-_text333=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive334=== CONT TestPathInfoCACompatibility/old_string_format_-_text335--- PASS: TestPathInfoCACompatibility (0.01s)336 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)337 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)338 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)339 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)340 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)341=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)342=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI343=== CONT TestUploadMultipart_SupersededByPeer/exists344--- PASS: TestScriptTokenBadJSON (0.05s)345=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon346=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512347--- PASS: TestPathInfoHashCompatibility (0.01s)348 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)349 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)350 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)351 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)352=== CONT TestUploadMultipart_SupersededByPeer/missing353--- PASS: TestScriptTokenEmptyToken (0.06s)354=== CONT TestSetClientTLS/rejects_connection_without_client_cert3552026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:500173562026/11/03 08:15:45 WARN Rate limiter enabled after throttle name=server-test rate=53572026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:500123582026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:500183592026/11/03 08:15:45 WARN Rate limiter backed off name=server-test rate=5360--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.04s)361=== CONT TestConvertHashToNix32/SRI_format_to_Nix32362=== CONT TestConvertHashToNix32/invalid_format363=== CONT TestConvertHashToNix32/already_Nix32_format364--- PASS: TestConvertHashToNix32 (0.01s)365 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)366 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)367 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)368=== CONT TestSetClientTLS/preserves_debug_logging_transport369--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.05s)370=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA371--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.04s)372=== CONT TestEncodeNixBase32/test_string_hash373=== CONT TestEncodeNixBase32/empty_input374--- PASS: TestEncodeNixBase32 (0.01s)375 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)376 --- PASS: TestEncodeNixBase32/empty_input (0.00s)377=== CONT TestParsePathInfoJSON/Nix_format378=== CONT TestParsePathInfoJSON/whitespace_only379=== CONT TestParsePathInfoJSON/invalid_JSON380=== CONT TestParsePathInfoJSON/empty_input381=== CONT TestParsePathInfoJSON/Lix_format382--- PASS: TestParsePathInfoJSON (0.01s)383 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)384 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)385 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)386 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)387 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)388=== CONT TestSupersededNARStillUploadsListing/small_NAR3892026/11/03 08:15:45 WARN Rate limiter enabled after throttle name=server-test rate=53902026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:500303912026/11/03 08:15:45 WARN Rate limiter backed off name=server-test rate=5392=== CONT TestFilterOversizedClosures/no_limit_keeps_everything393=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3942026/11/03 08:15:45 INFO Garbage collection started3952026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:500173962026/11/03 08:15:45 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=03972026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:500173982026/11/03 08:15:45 WARN Garbage collection finished on another replica. Its statistics are not available here399--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.03s)400=== CONT TestSupersededNARStillUploadsListing/dump_cut_short401--- PASS: TestStreamPushRequestLine (0.08s)402=== CONT TestFilterOversizedClosures/all_closures_skipped4032026/11/03 08:15:45 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=50404=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped4052026/11/03 08:15:45 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=2000406--- PASS: TestFilterOversizedClosures (0.04s)407 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)408 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)409 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)410=== CONT TestSetClientTLSErrors/missing_cert_file411=== CONT TestPartSizeForNAR/zero_stays_at_minimum412=== CONT TestSetClientTLSErrors/invalid_ca_file413=== CONT TestSetClientTLSErrors/missing_ca_file4142026/11/03 08:15:45 INFO Uploading abc-hello (1.0GB)4152026/11/03 08:15:45 INFO Uploading abc-hello (1.0GB)416=== CONT TestSetClientTLSErrors/missing_key_file417=== CONT TestPartSizeForNAR/capped_at_5_GiB418=== CONT TestPartSizeForNAR/5_TiB_S3_max_object419=== CONT TestPartSizeForNAR/1_TiB420=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts421=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum422=== CONT TestPartSizeForNAR/small_stays_at_minimum423--- PASS: TestPartSizeForNAR (0.04s)424 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)425 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)426 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)427 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)428 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)429 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)430 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)431--- PASS: TestSetClientTLSErrors (0.06s)432 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)433 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)434 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)435 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)4362026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:500174372026/11/03 08:15:45 WARN Rate limiter enabled after throttle name=server-test rate=54382026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:500904392026/11/03 08:15:45 WARN Rate limiter enabled after throttle name=s3-test rate=54402026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:500174412026/11/03 08:15:45 WARN Rate limiter backed off name=server-test rate=5442--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)443 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.04s)444 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.04s)445--- PASS: TestRateLimiterFeedback (0.00s)446 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)447 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.04s)448 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.04s)449 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.04s)4502026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:500174512026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:500174522026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:500174532026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:500174542026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:500174552026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:50017456--- PASS: TestDumpPathWriterError (0.15s)4572026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:500174582026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:500174592026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:50017460--- PASS: TestRegisterUploadedObjectReusesConnections (0.11s)4612026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:500174622026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:500174632026/11/03 08:15:45 INFO Uploading abc-hello (1.0GB)464--- PASS: TestDumpPathSingleFile (0.19s)4652026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:500174662026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:500174672026/11/03 08:15:45 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:500174682026/11/03 08:15:45 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:50110/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:50110/part/2469--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.20s)470--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.23s)471--- PASS: TestScriptTokenCachesUntilRefresh (0.24s)4722026/11/03 08:15:45 http: TLS handshake error from 127.0.0.1:50079: read tcp 127.0.0.1:50011->127.0.0.1:50079: use of closed network connection473--- PASS: TestSetClientTLS (0.01s)474 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.10s)475 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.10s)476 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.19s)4772026/11/03 08:15:45 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:50110/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:50110/part/34782026/11/03 08:15:45 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"479--- PASS: TestCaseHackSuffix (0.25s)480--- PASS: TestDumpPathMatchesNix (0.32s)481--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.64s)482--- PASS: TestUploadMultipart_PartsInParallel (0.70s)483--- PASS: TestSupersededNARStillUploadsListing (0.04s)484 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.04s)485 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.04s)486 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.63s)4872026/11/03 08:15:46 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:50002/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:50002/api/uploads/complete4882026/11/03 08:15:46 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:50002/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:50002/api/uploads/complete4892026/11/03 08:15:46 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4902026/11/03 08:15:46 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4912026/11/03 08:15:46 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:50002/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:50002/api/uploads/complete4922026/11/03 08:15:46 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"493--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)494--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)495PASS496Running server tests...497The files belonging to this database system will be owned by user "_tribuchetbld3".498This user must also own the server process.499500The database cluster will be initialized with locale "C".501The default database encoding has accordingly been set to "SQL_ASCII".502The default text search configuration will be set to "english".503504Data page checksums are enabled.505506creating directory /private/var/tb/3/scratch/5f72cc1e653f715f/build/postgres434282069/data ... ok507creating subdirectories ... ok508selecting dynamic shared memory implementation ... posix509selecting default "max_connections" ... 100510selecting default "shared_buffers" ... 128MB511selecting default time zone ... UTC512creating configuration files ... ok513running bootstrap script ... ok514performing post-bootstrap initialization ... ok515syncing data to disk ... ok516517initdb: warning: enabling "trust" authentication for local connections518initdb: 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.519520Success. You can now start the database server using:521522 pg_ctl -D /private/var/tb/3/scratch/5f72cc1e653f715f/build/postgres434282069/data -l logfile start5235242026-11-03 08:15:50.340 UTC [23114] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5252026-11-03 08:15:50.341 UTC [23114] LOG: listening on Unix socket "/private/var/tb/3/scratch/5f72cc1e653f715f/build/postgres434282069/.s.PGSQL.5432"5262026-11-03 08:15:50.351 UTC [23127] LOG: database system was shut down at 2026-11-03 08:15:50 UTC5272026-11-03 08:15:50.353 UTC [23114] LOG: database system is ready to accept connections528/private/var/tb/3/scratch/5f72cc1e653f715f/build/postgres434282069:5432 - accepting connections529{"timestamp":"2026-11-03T08:15:54.89521Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"207fd034-aeb1-43c2-b48d-6b70f7674538","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(11)"}530{"timestamp":"2026-11-03T08:15:54.997689Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"33ab1da7-36b8-4513-a6ec-4a6c693a9da6","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(10)"}531=== RUN TestService_AuthMiddleware532=== PAUSE TestService_AuthMiddleware533=== RUN TestService_AuthMiddleware_MTLSProxyHeader534=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader535=== RUN TestService_AuthMiddleware_MTLSBoundSubjects536=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects537=== RUN TestService_ReadAuthMiddleware538=== PAUSE TestService_ReadAuthMiddleware539=== RUN TestService_AuthMiddleware_OIDC540=== PAUSE TestService_AuthMiddleware_OIDC541=== RUN TestService_RequireScope_OIDC542=== PAUSE TestService_RequireScope_OIDC543=== RUN TestService_ReadScope_PublicByDefault544=== PAUSE TestService_ReadScope_PublicByDefault545=== RUN TestCacheConfigHandler546=== PAUSE TestCacheConfigHandler547=== RUN TestCacheStatsHandler548=== PAUSE TestCacheStatsHandler549=== RUN TestClientCADerivations550=== PAUSE TestClientCADerivations551=== RUN TestClientErrorHandling552=== PAUSE TestClientErrorHandling553=== RUN TestClientIntegration554=== PAUSE TestClientIntegration555=== RUN TestClientMultipleUploads556=== PAUSE TestClientMultipleUploads557=== RUN TestClientWithDependencies558=== PAUSE TestClientWithDependencies559=== RUN TestClientSharedPathCommittedMidPush560=== PAUSE TestClientSharedPathCommittedMidPush561=== RUN TestPinProtectsFromGC562=== PAUSE TestPinProtectsFromGC563=== RUN TestClientPushesUseOnePush564=== PAUSE TestClientPushesUseOnePush565=== RUN TestClientFallsBackToClosures566=== PAUSE TestClientFallsBackToClosures567=== RUN TestDeleteClosuresRacingPins568=== PAUSE TestDeleteClosuresRacingPins569=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock570=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock571=== RUN TestResolveDBConnectionString572=== PAUSE TestResolveDBConnectionString573=== RUN TestConnectWaitsForAPeerMigration574=== PAUSE TestConnectWaitsForAPeerMigration575=== RUN TestLeadElectsOneAndHandsOver576=== PAUSE TestLeadElectsOneAndHandsOver577=== RUN TestLeadIncumbentWinsAfterRestart5782026/11/03 08:15:55 INFO lead: acquired remote=192.0.2.1:12345792026/11/03 08:15:56 INFO lead: released remote=192.0.2.1:12345802026/11/03 08:15:56 INFO lead: acquired remote=192.0.2.1:12345812026/11/03 08:15:57 INFO lead: released remote=192.0.2.1:1234582--- PASS: TestLeadIncumbentWinsAfterRestart (2.22s)583=== RUN TestLeadIncumbentAnnouncesAtOnce584=== PAUSE TestLeadIncumbentAnnouncesAtOnce585=== RUN TestLeadEndsOnShutdown586=== PAUSE TestLeadEndsOnShutdown587=== RUN TestLeadEndsWhenItsConnectionHangs5882026/11/03 08:15:57 INFO lead: acquired remote=192.0.2.1:12345892026-11-03 08:15:58.970 UTC [24064] FATAL: terminating connection due to administrator command5902026/11/03 08:15:59 INFO lead: acquired remote=192.0.2.1:12345912026/11/03 08:16:00 WARN lead: lock connection lost error="timeout: context deadline exceeded"5922026/11/03 08:16:00 INFO lead: released remote=192.0.2.1:12345932026/11/03 08:16:00 INFO lead: released remote=192.0.2.1:1234594--- PASS: TestLeadEndsWhenItsConnectionHangs (3.05s)595=== RUN TestGCAdvisoryLockBlocksConcurrentRun596=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun597=== RUN TestGCBugBareHashReferences598=== PAUSE TestGCBugBareHashReferences599=== RUN TestGCMetrics600=== PAUSE TestGCMetrics601=== RUN TestPushDedupSurvivesConcurrentGC602=== PAUSE TestPushDedupSurvivesConcurrentGC603=== RUN TestDeduplicatedObjectsRecordedAsPending604=== PAUSE TestDeduplicatedObjectsRecordedAsPending605=== RUN TestGCSweepSkipsPendingObjects606=== PAUSE TestGCSweepSkipsPendingObjects607=== RUN TestTombstonedObjectOfferedWithoutWaiting608=== PAUSE TestTombstonedObjectOfferedWithoutWaiting609=== RUN TestGCSweepDeliversEachKeyOnce610=== PAUSE TestGCSweepDeliversEachKeyOnce611=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection612=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection613=== RUN TestForceGCDuringPushOffersSweptObject614=== PAUSE TestForceGCDuringPushOffersSweptObject615=== RUN TestFailedS3DeleteKeepsTombstone616=== PAUSE TestFailedS3DeleteKeepsTombstone617=== RUN TestSweepSkipsRowsLockedByPush618=== PAUSE TestSweepSkipsRowsLockedByPush619=== RUN TestRegisterCompletedObjectNeedsPendingRow620=== PAUSE TestRegisterCompletedObjectNeedsPendingRow621=== RUN TestGetExistingObjectsLocksRows622=== PAUSE TestGetExistingObjectsLocksRows623=== RUN TestSweepRechecksPendingAfterLocking624=== PAUSE TestSweepRechecksPendingAfterLocking625=== RUN TestPushWaitsForSweepHoldingRow626=== PAUSE TestPushWaitsForSweepHoldingRow627=== RUN TestCommitRacingPendingCleanupKeepsObjects628=== PAUSE TestCommitRacingPendingCleanupKeepsObjects629=== RUN TestGCEndsOnShutdown630=== PAUSE TestGCEndsOnShutdown631=== RUN TestGCTaskStore_StartNew632=== PAUSE TestGCTaskStore_StartNew633=== RUN TestGCTaskStore_DeduplicateSameParams634=== PAUSE TestGCTaskStore_DeduplicateSameParams635=== RUN TestGCTaskStore_ConflictDifferentParams636=== PAUSE TestGCTaskStore_ConflictDifferentParams637=== RUN TestGCTaskStore_GetEmpty638=== PAUSE TestGCTaskStore_GetEmpty639=== RUN TestGCTaskStore_GetReturnsLatest640=== PAUSE TestGCTaskStore_GetReturnsLatest641=== RUN TestGCTaskStore_CompletedAllowsNewTask642=== PAUSE TestGCTaskStore_CompletedAllowsNewTask643=== RUN TestGCTaskStore_PhaseUpdates644=== PAUSE TestGCTaskStore_PhaseUpdates645=== RUN TestGCTaskStore_Fail646=== PAUSE TestGCTaskStore_Fail647=== RUN TestGracefulShutdownDrainsInflight648=== PAUSE TestGracefulShutdownDrainsInflight649=== RUN TestService_healthCheckHandler650=== PAUSE TestService_healthCheckHandler651=== RUN TestService_readinessHandler652=== PAUSE TestService_readinessHandler653=== RUN TestGenerateLandingPage654=== PAUSE TestGenerateLandingPage655=== RUN TestCacheConfigHandlerMaxNarSize656=== PAUSE TestCacheConfigHandlerMaxNarSize657=== RUN TestCreatePendingClosureRejectsOversizedNAR658=== PAUSE TestCreatePendingClosureRejectsOversizedNAR659=== RUN TestNARDeduplicationMetadataUploadBug660=== PAUSE TestNARDeduplicationMetadataUploadBug661=== RUN TestMetricsInventory662=== PAUSE TestMetricsInventory663=== RUN TestMetricsCommit664=== PAUSE TestMetricsCommit665=== RUN TestService_NativeMTLS666=== PAUSE TestService_NativeMTLS667=== RUN TestServerTLSConfig668=== PAUSE TestServerTLSConfig669=== RUN TestMultipartCleanup670=== PAUSE TestMultipartCleanup671=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded672=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded673=== RUN TestPendingCleanupUsesOneCutoff674=== PAUSE TestPendingCleanupUsesOneCutoff675=== RUN TestObjectStatsTrigger676=== PAUSE TestObjectStatsTrigger677=== RUN TestObjectStatsUpdatedOncePerCommit678=== PAUSE TestObjectStatsUpdatedOncePerCommit679=== RUN TestOrphanedObjectsGC680=== PAUSE TestOrphanedObjectsGC681=== RUN TestOrphanedObjectsGCStressTest682=== PAUSE TestOrphanedObjectsGCStressTest683=== RUN TestCreatePin_ReservedPins684=== PAUSE TestCreatePin_ReservedPins685=== RUN TestPresentReportsOnlyClosureRoots686=== PAUSE TestPresentReportsOnlyClosureRoots687=== RUN TestPresentRefreshesOnlyStaleClosures688=== PAUSE TestPresentRefreshesOnlyStaleClosures689=== RUN TestPresentNotReportedWhileGCDeletesClosure690=== PAUSE TestPresentNotReportedWhileGCDeletesClosure691=== RUN TestParseSingleRange692=== PAUSE TestParseSingleRange693=== RUN TestProxyHeadersOnlyTrustedOnSocket6942026/11/03 08:16:00 INFO Starting HTTP server address=proxy.sock6952026/11/03 08:16:00 INFO Starting HTTP server address=127.0.0.1:502276962026/11/03 08:16:00 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6972026/11/03 08:16:00 INFO Shutdown signal received, draining in-flight requests timeout=10s698--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.29s)699=== RUN TestIsValidCachePath700=== PAUSE TestIsValidCachePath701=== RUN TestReadProxyNarinfo702=== PAUSE TestReadProxyNarinfo703=== RUN TestReadProxyNarinfoAlreadyDecompressed704=== PAUSE TestReadProxyNarinfoAlreadyDecompressed705=== RUN TestReadProxyContentNegotiation706=== PAUSE TestReadProxyContentNegotiation707=== RUN TestReadProxyNarStreaming708=== PAUSE TestReadProxyNarStreaming709=== RUN TestReadProxy404710=== PAUSE TestReadProxy404711=== RUN TestReadProxyInvalidPath712=== PAUSE TestReadProxyInvalidPath713=== RUN TestReadProxyHead714=== PAUSE TestReadProxyHead715=== RUN TestReadProxyOutlastsServerWriteTimeout716=== PAUSE TestReadProxyOutlastsServerWriteTimeout717=== RUN TestReadProxyConditionalGet718=== PAUSE TestReadProxyConditionalGet719=== RUN TestReadProxyRootRedirectsToIndexHTML720=== PAUSE TestReadProxyRootRedirectsToIndexHTML721=== RUN TestReadProxyDisabled722=== PAUSE TestReadProxyDisabled723=== RUN TestReadRedirectNar724=== PAUSE TestReadRedirectNar725=== RUN TestReadRedirectKeepsNarinfoProxied726=== PAUSE TestReadRedirectKeepsNarinfoProxied727=== RUN TestReadProxyRangeRequest728=== PAUSE TestReadProxyRangeRequest729=== RUN TestReadRedirectUsesPublicS3URL730=== PAUSE TestReadRedirectUsesPublicS3URL731=== RUN TestPush_OverlappingRootsStoreOneRowPerKey732=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey733=== RUN TestPush_CompleteCommitsEveryRoot734=== PAUSE TestPush_CompleteCommitsEveryRoot735=== RUN TestPush_RepeatedRootCommitsOnce736=== PAUSE TestPush_RepeatedRootCommitsOnce737=== RUN TestPush_CompleteWaitsForCleanupOfThePush738=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush739=== RUN TestPush_RootsAreLockedInByteOrder740=== PAUSE TestPush_RootsAreLockedInByteOrder741=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit742=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit743=== RUN TestPush_RejectsBadRequests744=== PAUSE TestPush_RejectsBadRequests745=== RUN TestPush_SignsNarinfosOfItsPendingObjects746=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects747=== RUN TestRedundantMultipartUpload748=== PAUSE TestRedundantMultipartUpload749=== RUN TestCompleteMultipartUpload_ErrorButObjectExists750=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists751=== RUN TestCompletedNarNotReofferedAcrossClosures752=== PAUSE TestCompletedNarNotReofferedAcrossClosures753=== RUN TestPresignedUploadRegisteredBeforeCommit754=== PAUSE TestPresignedUploadRegisteredBeforeCommit755=== RUN TestService_Rustfstest756=== PAUSE TestService_Rustfstest757=== RUN TestParseSize758=== PAUSE TestParseSize759=== RUN TestSkippedUploadsHandler760=== PAUSE TestSkippedUploadsHandler761=== RUN TestSystemdListenerNotActivated762--- PASS: TestSystemdListenerNotActivated (0.00s)763=== RUN TestWatchdogBeatsWhenHealthy764--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)765=== RUN TestWatchdogSkipsWhenUnhealthy7662026/11/03 08:16:00 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/11/03 08:16:00 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/11/03 08:16:00 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/11/03 08:16:00 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/03 08:16:00 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/03 08:16:00 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/03 08:16:00 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/03 08:16:00 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/03 08:16:00 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/03 08:16:00 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"776--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)777=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle778=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle779=== RUN TestProxyWriteTimeout780=== PAUSE TestProxyWriteTimeout781=== RUN TestPendingClosureWriteTimeout782=== PAUSE TestPendingClosureWriteTimeout783=== RUN TestIsValidUploadKey784=== PAUSE TestIsValidUploadKey785=== RUN TestUploadHandlersRejectInvalidKeys786=== PAUSE TestUploadHandlersRejectInvalidKeys787=== RUN TestUploadHandlersRejectOversizedBody788=== PAUSE TestUploadHandlersRejectOversizedBody789=== RUN TestService_cleanupPendingClosuresHandler790=== PAUSE TestService_cleanupPendingClosuresHandler791=== RUN TestService_createPendingClosureHandler792=== PAUSE TestService_createPendingClosureHandler793=== RUN TestService_verifyS3Integrity794=== PAUSE TestService_verifyS3Integrity795=== RUN TestService_verifyS3ReuploadsStaleNarinfo796=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo797=== RUN TestCompleteMultipartUnregistered798=== PAUSE TestCompleteMultipartUnregistered799=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT800=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT801=== CONT TestReadProxyOutlastsServerWriteTimeout802=== CONT TestParseSingleRange803=== RUN TestParseSingleRange/none804=== PAUSE TestParseSingleRange/none805=== RUN TestParseSingleRange/unknown_unit806=== PAUSE TestParseSingleRange/unknown_unit807=== RUN TestParseSingleRange/multi-range_ignored808=== PAUSE TestParseSingleRange/multi-range_ignored809=== RUN TestParseSingleRange/malformed_no_dash810=== PAUSE TestParseSingleRange/malformed_no_dash811=== RUN TestParseSingleRange/malformed_both_empty812=== PAUSE TestParseSingleRange/malformed_both_empty813=== CONT TestRegisterCompletedObjectNeedsPendingRow814=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection815=== CONT TestGCSweepDeliversEachKeyOnce816=== CONT TestTombstonedObjectOfferedWithoutWaiting817=== RUN TestParseSingleRange/malformed_end_before_start818=== PAUSE TestParseSingleRange/malformed_end_before_start819=== RUN TestParseSingleRange/closed820=== PAUSE TestParseSingleRange/closed821=== RUN TestParseSingleRange/open-ended822=== PAUSE TestParseSingleRange/open-ended823=== RUN TestParseSingleRange/end_clamped_to_size824=== PAUSE TestParseSingleRange/end_clamped_to_size825=== RUN TestParseSingleRange/suffix826=== PAUSE TestParseSingleRange/suffix827=== RUN TestParseSingleRange/suffix_exceeds_size828=== PAUSE TestParseSingleRange/suffix_exceeds_size829=== RUN TestParseSingleRange/single_byte830=== CONT TestCacheConfigHandlerMaxNarSize831=== CONT TestReadProxyHead832=== CONT TestReadProxyInvalidPath833=== CONT TestReadProxy404834=== CONT TestReadProxyNarStreaming835=== CONT TestReadProxyContentNegotiation836=== CONT TestReadProxyNarinfoAlreadyDecompressed837=== CONT TestReadProxyNarinfo838=== CONT TestIsValidCachePath839=== CONT TestSweepSkipsRowsLockedByPush840=== CONT TestFailedS3DeleteKeepsTombstone841=== CONT TestForceGCDuringPushOffersSweptObject842=== CONT TestPresentNotReportedWhileGCDeletesClosure843=== CONT TestPresentRefreshesOnlyStaleClosures844=== CONT TestPresentReportsOnlyClosureRoots845=== CONT TestCreatePin_ReservedPins846=== CONT TestOrphanedObjectsGCStressTest847=== CONT TestService_AuthMiddleware848=== PAUSE TestParseSingleRange/single_byte849=== RUN TestParseSingleRange/start_past_EOF850=== PAUSE TestParseSingleRange/start_past_EOF851=== RUN TestParseSingleRange/start_far_past_EOF852=== PAUSE TestParseSingleRange/start_far_past_EOF853--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)854=== CONT TestObjectStatsUpdatedOncePerCommit855=== RUN TestIsValidCachePath/narinfo856=== PAUSE TestIsValidCachePath/narinfo857=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars858=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars859=== RUN TestIsValidCachePath/nar_zst860=== PAUSE TestIsValidCachePath/nar_zst861=== RUN TestIsValidCachePath/nar_xz862=== CONT TestOrphanedObjectsGC863=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale864=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows865=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows866=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check867=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check868=== PAUSE TestIsValidCachePath/nar_xz869=== RUN TestIsValidCachePath/nar_bz2870=== PAUSE TestIsValidCachePath/nar_bz2871=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale872=== CONT TestObjectStatsTrigger873=== RUN TestIsValidCachePath/nar_uncompressed874=== PAUSE TestIsValidCachePath/nar_uncompressed875=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh876=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh877=== CONT TestPendingCleanupUsesOneCutoff878=== RUN TestIsValidCachePath/ls879=== PAUSE TestIsValidCachePath/ls880=== RUN TestIsValidCachePath/log881=== PAUSE TestIsValidCachePath/log882=== RUN TestIsValidCachePath/realisation883=== PAUSE TestIsValidCachePath/realisation884=== RUN TestIsValidCachePath/nix-cache-info885=== PAUSE TestIsValidCachePath/nix-cache-info886=== RUN TestIsValidCachePath/index.html887=== PAUSE TestIsValidCachePath/index.html888=== RUN TestIsValidCachePath/traversal_parent889=== PAUSE TestIsValidCachePath/traversal_parent890=== RUN TestIsValidCachePath/traversal_in_middle891=== PAUSE TestIsValidCachePath/traversal_in_middle892=== RUN TestIsValidCachePath/invalid_char_e893=== PAUSE TestIsValidCachePath/invalid_char_e894=== RUN TestIsValidCachePath/invalid_char_u895=== PAUSE TestIsValidCachePath/invalid_char_u896=== RUN TestIsValidCachePath/random_path897=== PAUSE TestIsValidCachePath/random_path898=== RUN TestIsValidCachePath/empty899=== PAUSE TestIsValidCachePath/empty900=== RUN TestIsValidCachePath/leading_slash901=== PAUSE TestIsValidCachePath/leading_slash902=== RUN TestIsValidCachePath/wrong_extension903=== PAUSE TestIsValidCachePath/wrong_extension904=== RUN TestIsValidCachePath/short_hash905=== PAUSE TestIsValidCachePath/short_hash906=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded9072026/11/03 08:16:01 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50229/oidc9082026/11/03 08:16:04 INFO Received uploads request method=POST path=/api/pending_closures909--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (5.04s)910=== CONT TestMultipartCleanup911--- PASS: TestReadProxyHead (5.99s)912=== CONT TestServerTLSConfig913=== RUN TestServerTLSConfig/no_client_CA914=== PAUSE TestServerTLSConfig/no_client_CA915=== RUN TestServerTLSConfig/missing_CA_file916=== PAUSE TestServerTLSConfig/missing_CA_file917=== RUN TestServerTLSConfig/not_a_PEM_file918=== PAUSE TestServerTLSConfig/not_a_PEM_file919=== CONT TestService_NativeMTLS9202026/11/03 08:16:07 INFO Received uploads request method=POST path=/api/pending_closures921--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (6.86s)922=== CONT TestMetricsCommit9232026/11/03 08:16:08 INFO Aborted multipart uploads count=0 kept=09242026/11/03 08:16:08 WARN Force mode enabled - objects will be deleted immediately without grace period9252026/11/03 08:16:08 INFO Received uploads request method=POST path=/api/pending_closures926--- PASS: TestTombstonedObjectOfferedWithoutWaiting (7.47s)927=== CONT TestMetricsInventory9282026/11/03 08:16:08 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=09292026/11/03 08:16:08 INFO Vacuumed table table=pending_closures9302026/11/03 08:16:08 INFO Vacuumed table table=pending_objects9312026/11/03 08:16:08 INFO Vacuumed table table=multipart_uploads9322026/11/03 08:16:08 INFO Vacuumed table table=closures9332026/11/03 08:16:08 INFO Vacuumed table table=objects934--- PASS: TestGCSweepDeliversEachKeyOnce (7.90s)935=== CONT TestNARDeduplicationMetadataUploadBug936--- PASS: TestPresentRefreshesOnlyStaleClosures (7.93s)937=== CONT TestCreatePendingClosureRejectsOversizedNAR9382026/11/03 08:16:08 INFO Received uploads request method=POST path=/api/pending_closures939--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)940=== CONT TestCompletedNarNotReofferedAcrossClosures941--- PASS: TestObjectStatsUpdatedOncePerCommit (8.47s)942=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT943--- PASS: TestReadProxyNarStreaming (8.94s)944=== CONT TestCompleteMultipartUnregistered9452026/11/03 08:16:10 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"946--- PASS: TestService_AuthMiddleware (9.68s)947=== CONT TestService_verifyS3ReuploadsStaleNarinfo948=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed949=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed950=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed951=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed952=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost953=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost954=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed955=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed956=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed957=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed958=== CONT TestService_verifyS3Integrity959--- PASS: TestRegisterCompletedObjectNeedsPendingRow (10.08s)960=== CONT TestService_createPendingClosureHandler961--- PASS: TestReadProxyContentNegotiation (10.63s)962=== CONT TestService_cleanupPendingClosuresHandler9632026/11/03 08:16:11 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9642026/11/03 08:16:11 WARN Refused reserved pin name=worker-x86_64-linux9652026/11/03 08:16:11 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9662026/11/03 08:16:11 INFO Received create pin request method=POST path=/api/pins/my-app9672026/11/03 08:16:11 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux968--- PASS: TestCreatePin_ReservedPins (10.86s)969=== CONT TestUploadHandlersRejectOversizedBody970=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure971=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure972=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart973=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart974=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts975=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts976=== CONT TestUploadHandlersRejectInvalidKeys977=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info978=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info979=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal980=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal981=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key982=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key983=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key984=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key985=== CONT TestIsValidUploadKey986=== RUN TestIsValidUploadKey/narinfo987=== PAUSE TestIsValidUploadKey/narinfo988=== RUN TestIsValidUploadKey/nar_zst989=== PAUSE TestIsValidUploadKey/nar_zst990=== RUN TestIsValidUploadKey/nar_xz991=== PAUSE TestIsValidUploadKey/nar_xz992=== RUN TestIsValidUploadKey/nar_plain993=== PAUSE TestIsValidUploadKey/nar_plain994=== RUN TestIsValidUploadKey/listing995=== PAUSE TestIsValidUploadKey/listing996=== RUN TestIsValidUploadKey/build_log997=== PAUSE TestIsValidUploadKey/build_log998=== RUN TestIsValidUploadKey/build_log_home-manager_file999=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1000=== RUN TestIsValidUploadKey/build_log_plus_in_name1001=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1002=== RUN TestIsValidUploadKey/build_log_question_mark1003=== PAUSE TestIsValidUploadKey/build_log_question_mark1004=== RUN TestIsValidUploadKey/build_log_equals1005=== PAUSE TestIsValidUploadKey/build_log_equals1006=== RUN TestIsValidUploadKey/realisation1007=== PAUSE TestIsValidUploadKey/realisation1008=== RUN TestIsValidUploadKey/realisation_plus_in_output1009=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1010=== RUN TestIsValidUploadKey/nix-cache-info1011=== PAUSE TestIsValidUploadKey/nix-cache-info1012=== RUN TestIsValidUploadKey/index.html1013=== PAUSE TestIsValidUploadKey/index.html1014=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1015=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1016=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1017=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1018=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1019=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1020=== RUN TestIsValidUploadKey/traversal1021=== PAUSE TestIsValidUploadKey/traversal1022=== RUN TestIsValidUploadKey/traversal_nar1023=== PAUSE TestIsValidUploadKey/traversal_nar1024=== RUN TestIsValidUploadKey/absolute1025=== PAUSE TestIsValidUploadKey/absolute1026=== RUN TestIsValidUploadKey/empty_key1027=== PAUSE TestIsValidUploadKey/empty_key1028=== RUN TestIsValidUploadKey/unknown_type1029=== PAUSE TestIsValidUploadKey/unknown_type1030=== CONT TestPendingClosureWriteTimeout1031=== RUN TestPendingClosureWriteTimeout/empty1032=== PAUSE TestPendingClosureWriteTimeout/empty1033=== RUN TestPendingClosureWriteTimeout/400_objects1034=== PAUSE TestPendingClosureWriteTimeout/400_objects1035=== RUN TestPendingClosureWriteTimeout/670k_objects1036=== PAUSE TestPendingClosureWriteTimeout/670k_objects1037=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1038=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1039=== CONT TestProxyWriteTimeout1040=== RUN TestProxyWriteTimeout/narinfo1041=== PAUSE TestProxyWriteTimeout/narinfo1042=== RUN TestProxyWriteTimeout/1_GiB_nar1043=== PAUSE TestProxyWriteTimeout/1_GiB_nar1044=== RUN TestProxyWriteTimeout/10_GiB_nar1045=== PAUSE TestProxyWriteTimeout/10_GiB_nar1046=== RUN TestProxyWriteTimeout/unknown_size1047=== PAUSE TestProxyWriteTimeout/unknown_size1048=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1049--- PASS: TestReadProxy404 (11.85s)1050=== CONT TestSkippedUploadsHandler10512026/11/03 08:16:12 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001052--- PASS: TestSkippedUploadsHandler (0.00s)1053=== CONT TestParseSize1054--- PASS: TestParseSize (0.00s)1055=== CONT TestService_Rustfstest10562026/11/03 08:16:12 INFO Received uploads request method=POST path=/api/pending_closures10572026/11/03 08:16:13 INFO Received uploads request method=POST path=/api/pending_closures10582026/11/03 08:16:13 INFO Received cleanup request method=DELETE path=/api/pending_closures10592026/11/03 08:16:13 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1060--- PASS: TestReadProxyNarinfo (12.70s)1061=== CONT TestPresignedUploadRegisteredBeforeCommit1062--- PASS: TestReadProxyOutlastsServerWriteTimeout (12.87s)1063=== CONT TestPush_CompleteCommitsEveryRoot1064--- PASS: TestReadProxyNarinfoAlreadyDecompressed (13.12s)1065=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1066--- PASS: TestObjectStatsTrigger (13.68s)1067=== CONT TestRedundantMultipartUpload1068=== NAME TestOrphanedObjectsGC1069 orphaned_objects_gc_test.go:287: GC Test Summary:1070 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1071 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1072 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1073 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1074 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1075--- PASS: TestOrphanedObjectsGC (14.44s)1076=== CONT TestPush_SignsNarinfosOfItsPendingObjects10772026/11/03 08:16:15 INFO Aborted multipart uploads count=0 kept=010782026/11/03 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period10792026/11/03 08:16:15 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=010802026/11/03 08:16:15 INFO Vacuumed table table=pending_closures10812026/11/03 08:16:15 INFO Vacuumed table table=pending_objects10822026/11/03 08:16:15 INFO Vacuumed table table=multipart_uploads10832026/11/03 08:16:15 INFO Vacuumed table table=closures10842026/11/03 08:16:15 INFO Vacuumed table table=objects10852026/11/03 08:16:15 INFO Aborted multipart uploads count=0 kept=010862026/11/03 08:16:15 WARN Force mode enabled - objects will be deleted immediately without grace period1087--- PASS: TestReadProxyInvalidPath (14.89s)1088=== CONT TestPush_RejectsBadRequests10892026/11/03 08:16:16 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=010902026/11/03 08:16:16 INFO Vacuumed table table=pending_closures10912026/11/03 08:16:16 INFO Vacuumed table table=pending_objects10922026/11/03 08:16:16 INFO Vacuumed table table=multipart_uploads10932026/11/03 08:16:16 INFO Vacuumed table table=closures10942026/11/03 08:16:16 INFO Vacuumed table table=objects1095--- PASS: TestSweepSkipsRowsLockedByPush (15.17s)1096=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1097--- PASS: TestPresentReportsOnlyClosureRoots (15.50s)1098=== CONT TestPush_RootsAreLockedInByteOrder10992026/11/03 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures11002026/11/03 08:16:17 INFO Aborted multipart uploads count=0 kept=011012026/11/03 08:16:17 WARN Force mode enabled - objects will be deleted immediately without grace period11022026/11/03 08:16:17 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."11032026/11/03 08:16:17 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1104--- PASS: TestFailedS3DeleteKeepsTombstone (16.21s)1105=== CONT TestPush_CompleteWaitsForCleanupOfThePush11062026/11/03 08:16:17 WARN mTLS auth: subject not in bound subjects subject="CN=reader"11072026/11/03 08:16:17 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1108--- PASS: TestService_NativeMTLS (10.26s)1109=== CONT TestPush_RepeatedRootCommitsOnce11102026/11/03 08:16:17 INFO Received uploads request method=POST path=/api/pending_closures11112026/11/03 08:16:17 INFO Received cleanup request method=DELETE path=/api/pending_closures11122026/11/03 08:16:17 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket29/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""11132026/11/03 08:16:17 INFO Aborted multipart uploads count=0 kept=111142026/11/03 08:16:17 INFO Received cleanup request method=DELETE path=/api/pending_closures11152026/11/03 08:16:17 INFO Aborted multipart uploads count=1 kept=01116--- PASS: TestMultipartCleanup (11.65s)1117=== CONT TestReadRedirectKeepsNarinfoProxied11182026/11/03 08:16:17 INFO Received push request method=POST path=/api/pushes11192026/11/03 08:16:18 INFO Received complete push request method=POST path=/api/pushes/1/complete11202026/11/03 08:16:18 INFO Completed push id=1 objects=4 duration=48.107333ms11212026/11/03 08:16:18 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11222026/11/03 08:16:18 INFO Completed upload id=2 objects=2 duration=2.274208ms1123--- PASS: TestMetricsCommit (10.35s)1124=== CONT TestPush_OverlappingRootsStoreOneRowPerKey1125--- PASS: TestMetricsInventory (10.08s)1126=== CONT TestReadRedirectUsesPublicS3URL11272026/11/03 08:16:19 INFO Received uploads request method=POST path=/api/pending_closures11282026/11/03 08:16:19 INFO Aborted multipart uploads count=1 kept=01129=== NAME TestNARDeduplicationMetadataUploadBug1130 metadata_upload_test.go:48: First store path: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestNARDeduplicationMetadataUploadBug2776798926/001/store/yzsiqn647202mj13pjkkikmsck8kwjmc-file1.txt11312026/11/03 08:16:19 INFO Received cleanup request method=DELETE path=/api/pending_closures11322026/11/03 08:16:19 INFO Aborted multipart uploads count=1 kept=01133--- PASS: TestPendingCleanupUsesOneCutoff (18.27s)1134=== CONT TestReadProxyRangeRequest11352026/11/03 08:16:19 INFO Received uploads request method=POST path=/api/pending_closures11362026/11/03 08:16:19 INFO Received push request method=POST path=/api/pushes1137--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (10.44s)1138=== CONT TestClientPushesUseOnePush11392026/11/03 08:16:19 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11402026/11/03 08:16:19 INFO Uploading yzsiqn647202mj13pjkkikmsck8kwjmc-file1.txt (160B)11412026/11/03 08:16:20 WARN Failed to register uploaded object key=yzsiqn647202mj13pjkkikmsck8kwjmc.ls error="server returned 404: 404 page not found\n"11422026/11/03 08:16:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11432026/11/03 08:16:20 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11442026/11/03 08:16:20 INFO Signed narinfos id=1 count=111452026/11/03 08:16:20 INFO Uploading 1 narinfos11462026/11/03 08:16:20 INFO Received complete push request method=POST path=/api/pushes/1/complete11472026/11/03 08:16:20 WARN Failed to register uploaded object key=yzsiqn647202mj13pjkkikmsck8kwjmc.narinfo error="server returned 404: 404 page not found\n"11482026/11/03 08:16:20 INFO Completed push id=1 objects=3 duration=25.608209ms11492026/11/03 08:16:20 INFO Upload complete. (955ms)1150=== NAME TestNARDeduplicationMetadataUploadBug1151 metadata_upload_test.go:54: Retrieved narinfo from S3:1152 StorePath: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestNARDeduplicationMetadataUploadBug2776798926/001/store/yzsiqn647202mj13pjkkikmsck8kwjmc-file1.txt1153 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1154 Compression: zstd1155 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1156 NarSize: 1601157 References: 1158 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1159 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1160 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1161 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}11622026/11/03 08:16:20 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11632026/11/03 08:16:20 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1164--- PASS: TestCompleteMultipartUnregistered (10.49s)1165=== CONT TestGCSweepSkipsPendingObjects1166=== NAME TestNARDeduplicationMetadataUploadBug1167 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestNARDeduplicationMetadataUploadBug2776798926/001/store/r8p6yr522ipih5wvzsajj0gag27axwxb-file2.txt11682026/11/03 08:16:21 INFO Received uploads request method=POST path=/api/pending_closures11692026/11/03 08:16:21 INFO Received push request method=POST path=/api/pushes11702026/11/03 08:16:21 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11712026/11/03 08:16:21 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11722026/11/03 08:16:21 INFO Signed narinfos id=2 count=111732026/11/03 08:16:21 WARN Failed to register uploaded object key=r8p6yr522ipih5wvzsajj0gag27axwxb.ls error="server returned 404: 404 page not found\n"11742026/11/03 08:16:21 INFO Uploading 1 narinfos11752026/11/03 08:16:21 INFO Received complete push request method=POST path=/api/pushes/2/complete11762026/11/03 08:16:21 WARN Failed to register uploaded object key=r8p6yr522ipih5wvzsajj0gag27axwxb.narinfo error="server returned 404: 404 page not found\n"11772026/11/03 08:16:21 INFO Completed push id=2 objects=3 duration=5.068125ms11782026/11/03 08:16:21 INFO Upload complete. (623ms)1179 metadata_upload_test.go:76: Retrieved narinfo from S3:1180 StorePath: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestNARDeduplicationMetadataUploadBug2776798926/001/store/r8p6yr522ipih5wvzsajj0gag27axwxb-file2.txt1181 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1182 Compression: zstd1183 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1184 NarSize: 1601185 References: 1186 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1187 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1188 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1189 {"version":1,"root":{"type":"regular","size":44}}1190--- PASS: TestNARDeduplicationMetadataUploadBug (12.61s)1191=== CONT TestDeduplicatedObjectsRecordedAsPending11922026/11/03 08:16:21 INFO Received uploads request method=POST path=/api/pending_closures11932026/11/03 08:16:21 INFO Received uploads request method=POST path=/api/pending_closures11942026/11/03 08:16:21 INFO Received uploads request method=POST path=/api/pending_closures11952026/11/03 08:16:22 INFO Received cleanup request method=DELETE path=/api/pending_closures11962026/11/03 08:16:22 INFO Aborted multipart uploads count=0 kept=011972026/11/03 08:16:22 INFO Received uploads request method=POST path=/api/pending_closures11982026/11/03 08:16:22 INFO Received cleanup request method=DELETE path=/api/pending_closures11992026/11/03 08:16:22 INFO Aborted multipart uploads count=1 kept=012002026/11/03 08:16:22 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12012026-11-03 08:16:22.230 UTC [25342] ERROR: Closure does not exist: id=112022026-11-03 08:16:22.230 UTC [25342] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE12032026-11-03 08:16:22.230 UTC [25342] STATEMENT: -- name: CommitPendingClosure :one1204 SELECT commit_pending_closure($1::bigint)::bigint1205 1206--- PASS: TestService_cleanupPendingClosuresHandler (10.66s)1207=== CONT TestPushDedupSurvivesConcurrentGC12082026/11/03 08:16:22 INFO Received uploads request method=POST path=/api/pending_closures12092026/11/03 08:16:22 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12102026/11/03 08:16:22 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLmJiNDA4Y2QwLTBiNmItNDJhMS1hNGYxLTFjMjU1NWRhOTQwN3gxNzkzNjkzNzc5MjAwMjQ1MDAw parts=1212112026/11/03 08:16:22 INFO Received uploads request method=POST path=/api/pending_closures1212--- PASS: TestCompletedNarNotReofferedAcrossClosures (13.74s)1213=== CONT TestGCMetrics1214--- PASS: TestService_Rustfstest (10.12s)1215=== CONT TestGCBugBareHashReferences12162026/11/03 08:16:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12172026/11/03 08:16:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12182026/11/03 08:16:23 INFO Received uploads request method=POST path=/api/pending_closures12192026/11/03 08:16:23 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLjIzN2YyNWEwLWZiM2UtNGI4NS1iNzNmLWM2YzM0NDVhN2Y2MHgxNzkzNjkzNzgxMDk0NjcyMDAw parts=1012202026/11/03 08:16:23 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12212026/11/03 08:16:23 INFO Completed upload id=1 objects=2 duration=61.075375ms12222026/11/03 08:16:23 INFO Received uploads request method=POST path=/api/pending_closures12232026/11/03 08:16:23 INFO Received uploads request method=POST path=/api/pending_closures12242026/11/03 08:16:23 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo12252026/11/03 08:16:23 WARN Found objects in DB but missing from S3, will re-upload count=11226--- PASS: TestService_verifyS3Integrity (13.01s)1227=== CONT TestGCAdvisoryLockBlocksConcurrentRun12282026/11/03 08:16:23 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst12292026/11/03 08:16:23 INFO Received uploads request method=POST path=/api/pending_closures1230--- PASS: TestPresignedUploadRegisteredBeforeCommit (10.05s)1231=== CONT TestLeadEndsOnShutdown12322026/11/03 08:16:23 INFO Received push request method=POST path=/api/pushes12332026/11/03 08:16:23 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12342026/11/03 08:16:24 INFO Received complete push request method=POST path=/api/pushes/1/complete12352026/11/03 08:16:24 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLjY1YjM4YmU3LWY2NGEtNDI2Yi04Mzc5LWU0ZDBmN2Q2ZTFlZngxNzkzNjkzNzgxNjg1OTgyMDAw parts=1012362026/11/03 08:16:24 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12372026/11/03 08:16:24 INFO Completed push id=1 objects=6 duration=67.892875ms1238--- PASS: TestPush_CompleteCommitsEveryRoot (10.30s)1239=== CONT TestLeadIncumbentAnnouncesAtOnce12402026/11/03 08:16:24 INFO Completed upload id=1 objects=2 duration=39.366584ms12412026/11/03 08:16:24 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000012422026/11/03 08:16:24 INFO Received uploads request method=POST path=/api/pending_closures12432026/11/03 08:16:24 INFO Starting cleanup of old closures method=DELETE path=/api/closures12442026/11/03 08:16:24 INFO Aborted multipart uploads count=0 kept=012452026/11/03 08:16:24 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=012462026/11/03 08:16:24 INFO Vacuumed table table=pending_closures12472026/11/03 08:16:24 INFO Received uploads request method=POST path=/api/pending_closures12482026/11/03 08:16:24 INFO Vacuumed table table=pending_objects12492026/11/03 08:16:24 INFO Vacuumed table table=multipart_uploads12502026/11/03 08:16:24 INFO Vacuumed table table=closures12512026/11/03 08:16:24 INFO Vacuumed table table=objects12522026/11/03 08:16:24 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001253--- PASS: TestService_createPendingClosureHandler (13.62s)1254=== CONT TestLeadElectsOneAndHandsOver12552026/11/03 08:16:24 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12562026/11/03 08:16:24 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLjhlMzE0MjU1LWU1MmEtNDg2Mi1hYTUyLTYyYjg4MGEzNWI5YngxNzkzNjkzNzg0NDk3ODExMDAw12572026/11/03 08:16:24 INFO Received uploads request method=POST path=/api/pending_closures12582026/11/03 08:16:24 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLjhlMzE0MjU1LWU1MmEtNDg2Mi1hYTUyLTYyYjg4MGEzNWI5YngxNzkzNjkzNzg0NDk3ODExMDAw parts=11259--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (10.86s)1260=== CONT TestConnectWaitsForAPeerMigration12612026/11/03 08:16:25 INFO Received uploads request method=POST path=/api/pending_closures12622026/11/03 08:16:25 INFO Received push request method=POST path=/api/pushes12632026/11/03 08:16:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12642026/11/03 08:16:25 INFO Signed narinfos id=1 count=112652026/11/03 08:16:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12662026/11/03 08:16:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12672026/11/03 08:16:25 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"12682026/11/03 08:16:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12692026/11/03 08:16:25 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"12702026/11/03 08:16:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12712026/11/03 08:16:25 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=112722026/11/03 08:16:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12732026/11/03 08:16:25 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1274--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (10.14s)1275=== CONT TestResolveDBConnectionString1276=== RUN TestResolveDBConnectionString/flag_wins1277=== PAUSE TestResolveDBConnectionString/flag_wins1278=== RUN TestResolveDBConnectionString/file_when_flag_empty1279=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1280=== RUN TestResolveDBConnectionString/missing_file_is_an_error1281=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1282=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1283=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1284=== RUN TestResolveDBConnectionString/nothing_configured1285=== PAUSE TestResolveDBConnectionString/nothing_configured1286=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock1287=== RUN TestPush_RejectsBadRequests/no_roots1288=== PAUSE TestPush_RejectsBadRequests/no_roots1289=== RUN TestPush_RejectsBadRequests/no_objects1290=== PAUSE TestPush_RejectsBadRequests/no_objects1291=== RUN TestPush_RejectsBadRequests/bad_root1292=== PAUSE TestPush_RejectsBadRequests/bad_root1293=== RUN TestPush_RejectsBadRequests/root_not_in_objects1294=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1295=== CONT TestDeleteClosuresRacingPins12962026/11/03 08:16:26 INFO Received push request method=POST path=/api/pushes12972026/11/03 08:16:26 INFO Received complete push request method=POST path=/api/pushes/1/complete12982026/11/03 08:16:26 INFO Completed push id=1 objects=4 duration=63.60925ms12992026/11/03 08:16:26 INFO Received push request method=POST path=/api/pushes13002026/11/03 08:16:26 INFO Aborted multipart uploads count=0 kept=013012026/11/03 08:16:26 WARN Force mode enabled - objects will be deleted immediately without grace period13022026/11/03 08:16:26 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=013032026/11/03 08:16:26 INFO Vacuumed table table=pending_closures13042026/11/03 08:16:26 INFO Received push request method=POST path=/api/pushes13052026/11/03 08:16:26 INFO Vacuumed table table=pending_objects13062026/11/03 08:16:27 INFO Vacuumed table table=multipart_uploads13072026/11/03 08:16:27 INFO Vacuumed table table=closures13082026/11/03 08:16:27 INFO Vacuumed table table=objects13092026/11/03 08:16:27 INFO Received complete push request method=POST path=/api/pushes/2/complete13102026/11/03 08:16:27 INFO Completed push id=2 objects=4 duration=29.964084ms1311--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (11.10s)1312=== CONT TestClientFallsBackToClosures13132026-11-03 08:16:27.419 UTC [26112] ERROR: could not obtain lock on row in relation "closures"13142026-11-03 08:16:27.419 UTC [26112] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13152026-11-03 08:16:27.450 UTC [26112] ERROR: could not obtain lock on row in relation "closures"13162026-11-03 08:16:27.450 UTC [26112] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13172026-11-03 08:16:27.457 UTC [26112] ERROR: could not obtain lock on row in relation "closures"13182026-11-03 08:16:27.457 UTC [26112] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13192026-11-03 08:16:27.470 UTC [26112] ERROR: could not obtain lock on row in relation "closures"13202026-11-03 08:16:27.470 UTC [26112] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT13212026-11-03 08:16:27.477 UTC [26112] ERROR: could not obtain lock on row in relation "closures"13222026-11-03 08:16:27.477 UTC [26112] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1323--- PASS: TestPush_RootsAreLockedInByteOrder (11.13s)1324=== CONT TestGCTaskStore_ConflictDifferentParams1325--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1326=== CONT TestGCTaskStore_PhaseUpdates1327--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1328=== CONT TestGCTaskStore_CompletedAllowsNewTask1329--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1330=== CONT TestGCTaskStore_Fail1331--- PASS: TestGCTaskStore_Fail (0.00s)1332=== CONT TestGCTaskStore_GetReturnsLatest1333--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1334=== CONT TestGenerateLandingPage1335--- PASS: TestGenerateLandingPage (0.02s)1336=== CONT TestGCTaskStore_GetEmpty1337--- PASS: TestGCTaskStore_GetEmpty (0.00s)1338=== CONT TestService_readinessHandler13392026/11/03 08:16:27 INFO Received push request method=POST path=/api/pushes13402026/11/03 08:16:27 INFO Received complete push request method=POST path=/api/pushes/1/complete13412026/11/03 08:16:27 INFO Completed push id=1 objects=4 duration=66.001ms1342--- PASS: TestPush_RepeatedRootCommitsOnce (10.71s)1343=== CONT TestReadProxyDisabled13442026/11/03 08:16:27 WARN Rate limiter enabled after throttle name=s3-test rate=513452026/11/03 08:16:27 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1346=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1347 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101348 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001349--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (16.11s)1350=== CONT TestService_healthCheckHandler13512026/11/03 08:16:28 INFO Received push request method=POST path=/api/pushes13522026/11/03 08:16:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13532026/11/03 08:16:28 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLmY3Njg0YWM4LTgxOGQtNDUwYS1hZGEyLWI4NjEwMGEyY2Q0Y3gxNzkzNjkzNzg0OTk1OTUxMDAw parts=1213542026/11/03 08:16:28 INFO Received uploads request method=POST path=/api/pending_closures13552026/11/03 08:16:28 INFO Received uploads request method=POST path=/api/pending_closures13562026-11-03 08:16:28.765 UTC [26198] ERROR: Push does not exist: id=113572026-11-03 08:16:28.765 UTC [26198] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE13582026-11-03 08:16:28.765 UTC [26198] STATEMENT: SELECT commit_push($1)1359--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (11.64s)1360=== CONT TestReadRedirectNar1361--- PASS: TestReadRedirectKeepsNarinfoProxied (10.99s)1362=== CONT TestGracefulShutdownDrainsInflight13632026/11/03 08:16:28 INFO Starting HTTP server address=127.0.0.1:5040913642026/11/03 08:16:28 INFO Shutdown signal received, draining in-flight requests timeout=10s1365--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1366=== CONT TestPushWaitsForSweepHoldingRow1367=== NAME TestOrphanedObjectsGCStressTest1368 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1369 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion1370--- PASS: TestReadRedirectUsesPublicS3URL (11.00s)1371=== CONT TestGCTaskStore_DeduplicateSameParams1372--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1373=== CONT TestGetExistingObjectsLocksRows13742026/11/03 08:16:29 INFO Received push request method=POST path=/api/pushes1375--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (11.99s)1376=== CONT TestGCTaskStore_StartNew1377--- PASS: TestGCTaskStore_StartNew (0.00s)1378=== CONT TestSweepRechecksPendingAfterLocking1379--- PASS: TestReadProxyRangeRequest (11.50s)1380=== CONT TestGCEndsOnShutdown1381=== RUN TestGCEndsOnShutdown/before_the_run1382=== PAUSE TestGCEndsOnShutdown/before_the_run1383=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1384=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1385=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1386=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1387=== CONT TestCommitRacingPendingCleanupKeepsObjects13882026/11/03 08:16:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13892026/11/03 08:16:31 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLjllZTIxZjMwLTE3NTgtNGVkMS05M2U1LTk1MmRkMWY4N2Y3YngxNzkzNjkzNzg4NTQyNTA4MDAw error="Get \"http://127.0.0.1:1/bucket44/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"13902026/11/03 08:16:31 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLjA1Mzg2ZmQ5LTQxOWUtNGQzYi04Y2E1LTk0NjM2YmM5YTYzNXgxNzkzNjkzNzg4NDYzOTczMDAw parts=1213912026/11/03 08:16:31 INFO Received cleanup request method=DELETE path=/api/pending_closures13922026/11/03 08:16:31 INFO Aborted multipart uploads count=1 kept=01393--- PASS: TestRedundantMultipartUpload (17.10s)1394=== CONT TestReadProxyRootRedirectsToIndexHTML13952026/11/03 08:16:31 INFO Received uploads request method=POST path=/api/pending_closures13962026/11/03 08:16:32 INFO Aborted multipart uploads count=0 kept=013972026/11/03 08:16:32 WARN Force mode enabled - objects will be deleted immediately without grace period13982026/11/03 08:16:32 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=013992026/11/03 08:16:32 INFO Vacuumed table table=pending_closures14002026/11/03 08:16:32 INFO Vacuumed table table=pending_objects14012026/11/03 08:16:32 INFO Vacuumed table table=multipart_uploads14022026/11/03 08:16:32 INFO Vacuumed table table=closures14032026/11/03 08:16:32 INFO Received uploads request method=POST path=/api/pending_closures14042026/11/03 08:16:32 INFO Vacuumed table table=objects1405--- PASS: TestGCSweepSkipsPendingObjects (12.04s)1406--- PASS: TestDeduplicatedObjectsRecordedAsPending (10.96s)1407=== CONT TestCacheStatsHandler1408=== CONT TestPinProtectsFromGC14092026/11/03 08:16:32 INFO Received push request method=POST path=/api/pushes14102026/11/03 08:16:32 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)14112026/11/03 08:16:32 INFO Uploading 47jcdfrf505n2vvj29k5zg10apib8fwz-shared-dep (136B)14122026/11/03 08:16:32 INFO Uploading fq546fw88jqb6vx76qx25xlb95p3jij2-b (256B)14132026/11/03 08:16:32 WARN Failed to register uploaded object key=47jcdfrf505n2vvj29k5zg10apib8fwz.ls error="server returned 404: 404 page not found\n"14142026/11/03 08:16:32 WARN Failed to register uploaded object key=8zxi3z0z9aq2g7flq0dlg8ba64skkbw0.ls error="server returned 404: 404 page not found\n"14152026/11/03 08:16:32 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14162026/11/03 08:16:32 WARN Failed to register uploaded object key=fq546fw88jqb6vx76qx25xlb95p3jij2.ls error="server returned 404: 404 page not found\n"14172026/11/03 08:16:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14182026/11/03 08:16:32 WARN Failed to register uploaded object key=nar/1nab6kcayfavag1fah7sa8mf2la47q6fry0w9wwh5pcli8wj2szc.nar.zst error="server returned 404: 404 page not found\n"14192026/11/03 08:16:32 INFO Signed narinfos id=1 count=314202026/11/03 08:16:32 INFO Uploading 3 narinfos14212026/11/03 08:16:32 WARN Failed to register uploaded object key=8zxi3z0z9aq2g7flq0dlg8ba64skkbw0.narinfo error="server returned 404: 404 page not found\n"14222026/11/03 08:16:32 WARN Failed to register uploaded object key=fq546fw88jqb6vx76qx25xlb95p3jij2.narinfo error="server returned 404: 404 page not found\n"14232026/11/03 08:16:32 INFO Received complete push request method=POST path=/api/pushes/1/complete14242026/11/03 08:16:32 WARN Failed to register uploaded object key=47jcdfrf505n2vvj29k5zg10apib8fwz.narinfo error="server returned 404: 404 page not found\n"14252026/11/03 08:16:32 INFO Completed push id=1 objects=8 duration=112.8245ms14262026/11/03 08:16:32 INFO Upload complete. (498ms)1427=== NAME TestClientPushesUseOnePush1428 client_pushes_test.go:97: Retrieved narinfo from S3:1429 StorePath: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientPushesUseOnePush2888281279/001/store/47jcdfrf505n2vvj29k5zg10apib8fwz-shared-dep1430 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1431 Compression: zstd1432 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821433 NarSize: 1361434 References: 1435 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1436 client_pushes_test.go:97: Retrieved narinfo from S3:1437 StorePath: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientPushesUseOnePush2888281279/001/store/8zxi3z0z9aq2g7flq0dlg8ba64skkbw0-a1438 URL: nar/1nab6kcayfavag1fah7sa8mf2la47q6fry0w9wwh5pcli8wj2szc.nar.zst1439 Compression: zstd1440 NarHash: sha256:1nab6kcayfavag1fah7sa8mf2la47q6fry0w9wwh5pcli8wj2szc1441 NarSize: 2561442 References: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientPushesUseOnePush2888281279/001/store/47jcdfrf505n2vvj29k5zg10apib8fwz-shared-dep1443 CA: text:sha256:0w46fca8779p2331lgmyhdfpnfkbvdqh6ynyicr3276qn8iclmm41444 client_pushes_test.go:97: Retrieved narinfo from S3:1445 StorePath: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientPushesUseOnePush2888281279/001/store/fq546fw88jqb6vx76qx25xlb95p3jij2-b1446 URL: nar/1nab6kcayfavag1fah7sa8mf2la47q6fry0w9wwh5pcli8wj2szc.nar.zst1447 Compression: zstd1448 NarHash: sha256:1nab6kcayfavag1fah7sa8mf2la47q6fry0w9wwh5pcli8wj2szc1449 NarSize: 2561450 References: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientPushesUseOnePush2888281279/001/store/47jcdfrf505n2vvj29k5zg10apib8fwz-shared-dep1451 CA: text:sha256:0w46fca8779p2331lgmyhdfpnfkbvdqh6ynyicr3276qn8iclmm41452--- PASS: TestClientPushesUseOnePush (13.26s)1453=== CONT TestClientSharedPathCommittedMidPush14542026/11/03 08:16:33 INFO Received uploads request method=POST path=/api/pending_closures14552026/11/03 08:16:33 INFO Aborted multipart uploads count=0 kept=014562026/11/03 08:16:33 WARN Force mode enabled - objects will be deleted immediately without grace period14572026/11/03 08:16:33 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=014582026/11/03 08:16:33 INFO Aborted multipart uploads count=0 kept=014592026/11/03 08:16:33 INFO Vacuumed table table=pending_closures14602026/11/03 08:16:33 INFO Vacuumed table table=pending_objects14612026/11/03 08:16:33 INFO Vacuumed table table=multipart_uploads14622026/11/03 08:16:33 INFO Vacuumed table table=closures14632026/11/03 08:16:33 INFO Vacuumed table table=objects14642026/11/03 08:16:33 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=01465--- PASS: TestGCMetrics (10.97s)1466=== CONT TestService_AuthMiddleware_OIDC14672026/11/03 08:16:33 INFO Vacuumed table table=pending_closures14682026/11/03 08:16:33 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50455/oidc14692026/11/03 08:16:33 INFO Vacuumed table table=pending_objects14702026/11/03 08:16:33 INFO Vacuumed table table=multipart_uploads14712026/11/03 08:16:33 INFO Vacuumed table table=closures14722026/11/03 08:16:33 INFO Vacuumed table table=objects14732026/11/03 08:16:33 INFO Aborted multipart uploads count=0 kept=014742026/11/03 08:16:33 WARN Force mode enabled - objects will be deleted immediately without grace period14752026/11/03 08:16:33 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=014762026/11/03 08:16:33 INFO Vacuumed table table=pending_closures14772026/11/03 08:16:33 INFO Vacuumed table table=pending_objects14782026/11/03 08:16:33 INFO Vacuumed table table=multipart_uploads14792026/11/03 08:16:33 INFO Vacuumed table table=closures14802026/11/03 08:16:33 INFO Vacuumed table table=objects1481--- PASS: TestPushDedupSurvivesConcurrentGC (11.62s)1482=== CONT TestClientWithDependencies1483--- PASS: TestGCBugBareHashReferences (11.23s)1484=== CONT TestCacheConfigHandler1485=== RUN TestCacheConfigHandler/full_config,_no_issuer1486=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1487=== RUN TestCacheConfigHandler/no_cache_url_configured1488=== PAUSE TestCacheConfigHandler/no_cache_url_configured1489=== RUN TestCacheConfigHandler/no_signing_keys1490=== PAUSE TestCacheConfigHandler/no_signing_keys1491=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1492=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1493=== CONT TestClientMultipleUploads14942026/11/03 08:16:34 INFO lead: acquired remote=192.0.2.1:123414952026/11/03 08:16:34 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld3 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1496--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (11.31s)1497=== CONT TestService_ReadScope_PublicByDefault1498--- PASS: TestConnectWaitsForAPeerMigration (10.38s)1499=== CONT TestClientIntegration15002026/11/03 08:16:35 INFO lead: released remote=192.0.2.1:12341501--- PASS: TestLeadEndsOnShutdown (11.77s)1502=== CONT TestService_RequireScope_OIDC15032026/11/03 08:16:35 INFO lead: acquired remote=192.0.2.1:123415042026/11/03 08:16:35 INFO lead: released remote=192.0.2.1:12341505--- PASS: TestLeadIncumbentAnnouncesAtOnce (11.41s)1506=== CONT TestClientErrorHandling1507=== RUN TestClientErrorHandling/InvalidStorePath1508=== PAUSE TestClientErrorHandling/InvalidStorePath1509=== RUN TestClientErrorHandling/InvalidAuthToken1510=== PAUSE TestClientErrorHandling/InvalidAuthToken1511=== RUN TestClientErrorHandling/ServerNotAvailable1512=== PAUSE TestClientErrorHandling/ServerNotAvailable1513=== CONT TestClientCADerivations15142026/11/03 08:16:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50465/oidc15152026/11/03 08:16:36 INFO lead: acquired remote=192.0.2.1:123415162026/11/03 08:16:37 INFO lead: released remote=192.0.2.1:123415172026/11/03 08:16:37 INFO lead: acquired remote=192.0.2.1:123415182026/11/03 08:16:37 WARN readiness check failed error="closed pool"1519--- PASS: TestService_readinessHandler (10.35s)1520=== CONT TestReadProxyConditionalGet1521--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (12.83s)1522=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1523--- PASS: TestService_healthCheckHandler (10.46s)1524=== CONT TestService_ReadAuthMiddleware15252026/11/03 08:16:38 INFO lead: released remote=192.0.2.1:12341526--- PASS: TestLeadElectsOneAndHandsOver (13.81s)1527=== CONT TestService_AuthMiddleware_MTLSProxyHeader15282026/11/03 08:16:38 INFO Received uploads request method=POST path=/api/pending_closures15292026/11/03 08:16:38 INFO Received uploads request method=POST path=/api/pending_closures15302026/11/03 08:16:38 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15312026/11/03 08:16:38 INFO Uploading 2z5i8z70yj0c11nv0ay29ggs2ha1dfjw-a (256B)15322026/11/03 08:16:38 INFO Uploading i960ckypf6v91hsj23c8clcyy6c8y6zc-shared-dep (136B)15332026/11/03 08:16:38 WARN Failed to register uploaded object key=lc75h1nd7hi2hw2a3mcjhzdpd8l2rs58.ls error="server returned 404: 404 page not found\n"15342026/11/03 08:16:38 WARN Failed to register uploaded object key=2z5i8z70yj0c11nv0ay29ggs2ha1dfjw.ls error="server returned 404: 404 page not found\n"15352026/11/03 08:16:38 WARN Failed to register uploaded object key=i960ckypf6v91hsj23c8clcyy6c8y6zc.ls error="server returned 404: 404 page not found\n"15362026/11/03 08:16:38 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15372026/11/03 08:16:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15382026/11/03 08:16:38 WARN Failed to register uploaded object key=nar/05lk1bswqxgqvgqrgmy75lhlwf7fl6rx6svibpx1xayk9fr25vq3.nar.zst error="server returned 404: 404 page not found\n"15392026/11/03 08:16:38 INFO Signed narinfos id=1 count=215402026/11/03 08:16:38 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign1541--- PASS: TestReadProxyDisabled (11.00s)1542=== CONT TestParseSingleRange/none1543=== CONT TestParseSingleRange/suffix1544=== CONT TestParseSingleRange/start_far_past_EOF1545=== CONT TestParseSingleRange/start_past_EOF1546=== CONT TestParseSingleRange/single_byte1547=== CONT TestParseSingleRange/suffix_exceeds_size1548=== CONT TestParseSingleRange/malformed_end_before_start1549=== CONT TestParseSingleRange/end_clamped_to_size1550=== CONT TestParseSingleRange/open-ended1551=== CONT TestParseSingleRange/closed1552=== CONT TestParseSingleRange/malformed_no_dash1553=== CONT TestParseSingleRange/malformed_both_empty1554=== CONT TestParseSingleRange/multi-range_ignored1555=== CONT TestParseSingleRange/unknown_unit1556--- PASS: TestParseSingleRange (0.01s)1557 --- PASS: TestParseSingleRange/none (0.00s)1558 --- PASS: TestParseSingleRange/suffix (0.00s)1559 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1560 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1561 --- PASS: TestParseSingleRange/single_byte (0.00s)1562 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1563 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1564 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1565 --- PASS: TestParseSingleRange/open-ended (0.00s)1566 --- PASS: TestParseSingleRange/closed (0.00s)1567 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1568 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1569 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1570 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1571=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows15722026/11/03 08:16:38 INFO Signed narinfos id=2 count=215732026/11/03 08:16:38 INFO Uploading 4 narinfos15742026/11/03 08:16:39 WARN Failed to register uploaded object key=i960ckypf6v91hsj23c8clcyy6c8y6zc.narinfo error="server returned 404: 404 page not found\n"15752026/11/03 08:16:39 WARN Failed to register uploaded object key=lc75h1nd7hi2hw2a3mcjhzdpd8l2rs58.narinfo error="server returned 404: 404 page not found\n"15762026/11/03 08:16:39 WARN Failed to register uploaded object key=2z5i8z70yj0c11nv0ay29ggs2ha1dfjw.narinfo error="server returned 404: 404 page not found\n"15772026/11/03 08:16:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15782026/11/03 08:16:39 WARN Failed to register uploaded object key=i960ckypf6v91hsj23c8clcyy6c8y6zc.narinfo error="server returned 404: 404 page not found\n"15792026/11/03 08:16:39 INFO Completed upload id=1 objects=6 duration=47.246375ms15802026/11/03 08:16:39 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15812026/11/03 08:16:39 INFO Completed upload id=2 objects=6 duration=1.216541ms15822026/11/03 08:16:39 INFO Upload complete. (713ms)1583=== NAME TestClientFallsBackToClosures1584 client_pushes_test.go:112: Retrieved narinfo from S3:1585 StorePath: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientFallsBackToClosures2723025552/001/store/i960ckypf6v91hsj23c8clcyy6c8y6zc-shared-dep1586 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1587 Compression: zstd1588 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821589 NarSize: 1361590 References: 1591 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1592 client_pushes_test.go:112: Retrieved narinfo from S3:1593 StorePath: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientFallsBackToClosures2723025552/001/store/2z5i8z70yj0c11nv0ay29ggs2ha1dfjw-a1594 URL: nar/05lk1bswqxgqvgqrgmy75lhlwf7fl6rx6svibpx1xayk9fr25vq3.nar.zst1595 Compression: zstd1596 NarHash: sha256:05lk1bswqxgqvgqrgmy75lhlwf7fl6rx6svibpx1xayk9fr25vq31597 NarSize: 2561598 References: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientFallsBackToClosures2723025552/001/store/i960ckypf6v91hsj23c8clcyy6c8y6zc-shared-dep1599 CA: text:sha256:10n8in3yp4il8zhycqn7m655a14pvx4l3z8riibp7rg97pnsh52q1600 client_pushes_test.go:112: Retrieved narinfo from S3:1601 StorePath: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientFallsBackToClosures2723025552/001/store/lc75h1nd7hi2hw2a3mcjhzdpd8l2rs58-b1602 URL: nar/05lk1bswqxgqvgqrgmy75lhlwf7fl6rx6svibpx1xayk9fr25vq3.nar.zst1603 Compression: zstd1604 NarHash: sha256:05lk1bswqxgqvgqrgmy75lhlwf7fl6rx6svibpx1xayk9fr25vq31605 NarSize: 2561606 References: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientFallsBackToClosures2723025552/001/store/i960ckypf6v91hsj23c8clcyy6c8y6zc-shared-dep1607 CA: text:sha256:10n8in3yp4il8zhycqn7m655a14pvx4l3z8riibp7rg97pnsh52q1608--- PASS: TestClientFallsBackToClosures (12.07s)1609=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check16102026/11/03 08:16:39 INFO Received uploads request method=POST path=/api/pending_closures1611--- PASS: TestReadRedirectNar (11.04s)1612=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1613--- PASS: TestPushWaitsForSweepHoldingRow (11.04s)1614=== CONT TestIsValidCachePath/narinfo1615=== CONT TestIsValidCachePath/traversal_parent1616=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1617--- PASS: TestGetExistingObjectsLocksRows (10.82s)1618=== CONT TestIsValidCachePath/ls1619=== CONT TestIsValidCachePath/index.html1620=== CONT TestIsValidCachePath/nix-cache-info1621=== CONT TestIsValidCachePath/realisation1622=== CONT TestIsValidCachePath/log1623=== CONT TestIsValidCachePath/empty1624=== CONT TestIsValidCachePath/short_hash1625=== CONT TestIsValidCachePath/wrong_extension1626=== CONT TestIsValidCachePath/leading_slash1627=== CONT TestIsValidCachePath/invalid_char_u1628=== CONT TestIsValidCachePath/random_path1629=== CONT TestIsValidCachePath/nar_xz1630=== CONT TestIsValidCachePath/nar_uncompressed1631=== CONT TestIsValidCachePath/nar_bz21632=== CONT TestIsValidCachePath/invalid_char_e1633=== CONT TestIsValidCachePath/nar_zst1634=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1635=== CONT TestIsValidCachePath/traversal_in_middle1636--- PASS: TestIsValidCachePath (0.02s)1637 --- PASS: TestIsValidCachePath/narinfo (0.00s)1638 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1639 --- PASS: TestIsValidCachePath/ls (0.00s)1640 --- PASS: TestIsValidCachePath/index.html (0.00s)1641 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1642 --- PASS: TestIsValidCachePath/realisation (0.00s)1643 --- PASS: TestIsValidCachePath/log (0.00s)1644 --- PASS: TestIsValidCachePath/empty (0.00s)1645 --- PASS: TestIsValidCachePath/short_hash (0.00s)1646 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1647 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1648 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1649 --- PASS: TestIsValidCachePath/random_path (0.00s)1650 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1651 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1652 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1653 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1654 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1655 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1656 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1657=== CONT TestServerTLSConfig/no_client_CA1658=== CONT TestServerTLSConfig/not_a_PEM_file1659=== CONT TestServerTLSConfig/missing_CA_file1660--- PASS: TestServerTLSConfig (0.01s)1661 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1662 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.04s)1663 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1664=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed16652026/11/03 08:16:40 INFO Aborted multipart uploads count=0 kept=016662026/11/03 08:16:41 WARN Force mode enabled - objects will be deleted immediately without grace period16672026/11/03 08:16:41 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016682026/11/03 08:16:41 INFO Vacuumed table table=pending_closures16692026/11/03 08:16:41 INFO Vacuumed table table=pending_objects16702026/11/03 08:16:41 INFO Vacuumed table table=multipart_uploads16712026/11/03 08:16:41 INFO Vacuumed table table=closures16722026/11/03 08:16:41 INFO Vacuumed table table=objects1673--- PASS: TestSweepRechecksPendingAfterLocking (11.05s)1674=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed16752026/11/03 08:16:41 INFO Aborted multipart uploads count=0 kept=016762026/11/03 08:16:41 WARN Force mode enabled - objects will be deleted immediately without grace period16772026/11/03 08:16:41 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016782026/11/03 08:16:41 INFO Vacuumed table table=pending_closures16792026/11/03 08:16:41 INFO Vacuumed table table=pending_objects16802026/11/03 08:16:41 INFO Vacuumed table table=multipart_uploads16812026/11/03 08:16:41 INFO Vacuumed table table=closures16822026/11/03 08:16:41 INFO Vacuumed table table=objects1683--- PASS: TestCommitRacingPendingCleanupKeepsObjects (10.88s)1684=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed1685--- PASS: TestReadProxyRootRedirectsToIndexHTML (9.91s)1686=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1687--- PASS: TestCacheStatsHandler (9.83s)1688=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1689=== NAME TestPinProtectsFromGC1690 client_integration_test.go:778: Pinned store path: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestPinProtectsFromGC2197426107/001/store/j0yrx344nqqbwpf508pldv3adcfqv84d-pinned-file.txt1691 client_integration_test.go:779: Unpinned store path: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestPinProtectsFromGC2197426107/001/store/pmi8xidpm9z48vg9aq6nzpvzcnmic6wl-unpinned-file.txt16922026/11/03 08:16:43 INFO Received push request method=POST path=/api/pushes1693=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1694=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1695=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1696=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1697=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1698=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1699=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1700=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1701=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17022026/11/03 08:16:43 INFO Received uploads request method=POST path=/17032026/11/03 08:16:43 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17042026/11/03 08:16:43 INFO Uploading j0yrx344nqqbwpf508pldv3adcfqv84d-pinned-file.txt (128B)17052026/11/03 08:16:43 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17062026/11/03 08:16:43 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"17072026/11/03 08:16:43 WARN Failed to register uploaded object key=j0yrx344nqqbwpf508pldv3adcfqv84d.ls error="server returned 404: 404 page not found\n"17082026/11/03 08:16:43 INFO Signed narinfos id=1 count=117092026/11/03 08:16:43 INFO Uploading 1 narinfos17102026/11/03 08:16:43 INFO Received complete push request method=POST path=/api/pushes/1/complete17112026/11/03 08:16:43 WARN Failed to register uploaded object key=j0yrx344nqqbwpf508pldv3adcfqv84d.narinfo error="server returned 404: 404 page not found\n"17122026/11/03 08:16:43 INFO Completed push id=1 objects=3 duration=45.513584ms17132026/11/03 08:16:43 INFO Upload complete. (426ms)1714--- PASS: TestDeleteClosuresRacingPins (18.18s)1715=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17162026/11/03 08:16:44 INFO Received uploads request method=POST path=/1717=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17182026/11/03 08:16:44 INFO Received request for more parts method=POST path=/1719=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17202026/11/03 08:16:44 INFO Received complete multipart upload request method=POST path=/1721=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17222026/11/03 08:16:44 INFO Received complete multipart upload request method=POST path=/1723=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17242026/11/03 08:16:44 INFO Received request for more parts method=POST path=/1725=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17262026/11/03 08:16:44 INFO Received uploads request method=POST path=/1727--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1728 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1729 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1730 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1731 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1732=== CONT TestIsValidUploadKey/narinfo1733=== CONT TestIsValidUploadKey/realisation_plus_in_output1734=== CONT TestIsValidUploadKey/unknown_type1735=== CONT TestIsValidUploadKey/empty_key1736=== CONT TestIsValidUploadKey/absolute1737=== CONT TestIsValidUploadKey/traversal_nar1738=== CONT TestIsValidUploadKey/traversal1739=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1740=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1741=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1742=== CONT TestIsValidUploadKey/index.html1743=== CONT TestIsValidUploadKey/nix-cache-info1744=== CONT TestIsValidUploadKey/build_log_home-manager_file1745=== CONT TestIsValidUploadKey/realisation1746=== CONT TestIsValidUploadKey/build_log_equals1747=== CONT TestIsValidUploadKey/build_log_question_mark1748=== CONT TestIsValidUploadKey/build_log_plus_in_name1749=== CONT TestIsValidUploadKey/nar_plain1750=== CONT TestIsValidUploadKey/build_log1751=== CONT TestIsValidUploadKey/listing1752=== CONT TestIsValidUploadKey/nar_xz1753=== CONT TestIsValidUploadKey/nar_zst1754--- PASS: TestIsValidUploadKey (0.02s)1755 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1756 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1757 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1758 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1759 --- PASS: TestIsValidUploadKey/absolute (0.00s)1760 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1761 --- PASS: TestIsValidUploadKey/traversal (0.00s)1762 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1763 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1764 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1765 --- PASS: TestIsValidUploadKey/index.html (0.00s)1766 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1767 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1768 --- PASS: TestIsValidUploadKey/realisation (0.00s)1769 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1770 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1771 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1772 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1773 --- PASS: TestIsValidUploadKey/build_log (0.00s)1774 --- PASS: TestIsValidUploadKey/listing (0.00s)1775 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1776 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1777=== CONT TestPendingClosureWriteTimeout/empty1778=== CONT TestProxyWriteTimeout/narinfo1779=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline17802026/11/03 08:16:44 INFO Received push request method=POST path=/api/pushes17812026/11/03 08:16:44 INFO Received push request method=POST path=/api/pushes17822026/11/03 08:16:44 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)17832026/11/03 08:16:44 INFO Uploading yi1ql4xzhdl35v4kqyzlbg3gg3508xdd-shared-dep (136B)17842026/11/03 08:16:44 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)17852026/11/03 08:16:44 INFO Uploading 57r9fpgmsnl2crnb16gnmcya827033d4-top (264B)17862026/11/03 08:16:44 INFO Uploading pmi8xidpm9z48vg9aq6nzpvzcnmic6wl-unpinned-file.txt (128B)17872026/11/03 08:16:44 WARN Failed to register uploaded object key=yi1ql4xzhdl35v4kqyzlbg3gg3508xdd.ls error="server returned 404: 404 page not found\n"17882026/11/03 08:16:44 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"17892026/11/03 08:16:44 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign17902026/11/03 08:16:44 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17912026/11/03 08:16:44 WARN Failed to register uploaded object key=57r9fpgmsnl2crnb16gnmcya827033d4.ls error="server returned 404: 404 page not found\n"17922026/11/03 08:16:44 WARN Failed to register uploaded object key=pmi8xidpm9z48vg9aq6nzpvzcnmic6wl.ls error="server returned 404: 404 page not found\n"17932026/11/03 08:16:44 INFO Signed narinfos id=2 count=117942026/11/03 08:16:44 INFO Uploading 1 narinfos17952026/11/03 08:16:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17962026/11/03 08:16:44 INFO Signed narinfos id=1 count=217972026/11/03 08:16:44 INFO Uploading 2 narinfos17982026/11/03 08:16:44 WARN Failed to register uploaded object key=nar/0icgc2z8chzfiwh8j1h70msdrhndqsi838y4anbcda55xyvlaj4y.nar.zst error="server returned 404: 404 page not found\n"1799=== NAME TestClientMultipleUploads1800 client_integration_test.go:405: Created store path 0: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientMultipleUploads427340849/001/store/bv99az73g8shd8dcvlp53bln9zw85v5q-test-file-0.txt18012026/11/03 08:16:44 INFO Received complete push request method=POST path=/api/pushes/2/complete18022026/11/03 08:16:45 INFO Completed push id=2 objects=3 duration=25.417083ms1803--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)1804 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.42s)1805 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.12s)1806 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.51s)1807=== CONT TestPendingClosureWriteTimeout/670k_objects1808=== CONT TestPendingClosureWriteTimeout/400_objects1809=== CONT TestProxyWriteTimeout/10_GiB_nar1810=== CONT TestProxyWriteTimeout/unknown_size1811=== CONT TestProxyWriteTimeout/1_GiB_nar1812--- PASS: TestProxyWriteTimeout (0.00s)1813 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1814 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1815 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1816 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1817=== CONT TestResolveDBConnectionString/flag_wins1818=== CONT TestResolveDBConnectionString/PGHOST_allows_empty18192026/11/03 08:16:45 WARN Failed to register uploaded object key=pmi8xidpm9z48vg9aq6nzpvzcnmic6wl.narinfo error="server returned 404: 404 page not found\n"18202026/11/03 08:16:45 INFO Received complete push request method=POST path=/api/pushes/1/complete18212026/11/03 08:16:45 WARN Failed to register uploaded object key=57r9fpgmsnl2crnb16gnmcya827033d4.narinfo error="server returned 404: 404 page not found\n"1822=== CONT TestResolveDBConnectionString/nothing_configured1823=== CONT TestResolveDBConnectionString/missing_file_is_an_error1824=== CONT TestResolveDBConnectionString/file_when_flag_empty1825=== CONT TestPush_RejectsBadRequests/no_roots18262026/11/03 08:16:45 WARN Failed to register uploaded object key=yi1ql4xzhdl35v4kqyzlbg3gg3508xdd.narinfo error="server returned 404: 404 page not found\n"1827--- PASS: TestResolveDBConnectionString (0.04s)1828 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1829 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1830 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1831 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1832 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)18332026/11/03 08:16:45 INFO Upload complete. (851ms)18342026/11/03 08:16:45 INFO Received push request method=POST path=/api/pushes1835=== CONT TestPush_RejectsBadRequests/bad_root18362026/11/03 08:16:45 INFO Received push request method=POST path=/api/pushes1837=== CONT TestPush_RejectsBadRequests/root_not_in_objects18382026/11/03 08:16:45 INFO Received push request method=POST path=/api/pushes1839=== CONT TestPush_RejectsBadRequests/no_objects18402026/11/03 08:16:45 INFO Received push request method=POST path=/api/pushes1841=== CONT TestGCEndsOnShutdown/before_the_run1842--- PASS: TestPush_RejectsBadRequests (9.95s)1843 --- PASS: TestPush_RejectsBadRequests/no_roots (0.01s)1844 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1845 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1846 --- PASS: TestPush_RejectsBadRequests/no_objects (0.01s)18472026/11/03 08:16:45 INFO Completed push id=1 objects=6 duration=45.8675ms18482026/11/03 08:16:45 INFO Upload complete. (1.211s)1849--- PASS: TestService_ReadScope_PublicByDefault (10.13s)1850=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1851=== NAME TestClientSharedPathCommittedMidPush1852 client_integration_test.go:727: Retrieved narinfo from S3:1853 StorePath: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientSharedPathCommittedMidPush3146650699/001/store/yi1ql4xzhdl35v4kqyzlbg3gg3508xdd-shared-dep1854 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1855 Compression: zstd1856 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821857 NarSize: 1361858 References: 1859 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1860=== NAME TestClientWithDependencies1861 client_integration_test.go:660: Built derivation: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientWithDependencies2154866336/001/store/1qindxmzyvf2rzd4m6splk0pmg8n9yi2-test-script1862=== NAME TestClientSharedPathCommittedMidPush1863 client_integration_test.go:727: Retrieved narinfo from S3:1864 StorePath: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientSharedPathCommittedMidPush3146650699/001/store/57r9fpgmsnl2crnb16gnmcya827033d4-top1865 URL: nar/0icgc2z8chzfiwh8j1h70msdrhndqsi838y4anbcda55xyvlaj4y.nar.zst1866 Compression: zstd1867 NarHash: sha256:0icgc2z8chzfiwh8j1h70msdrhndqsi838y4anbcda55xyvlaj4y1868 NarSize: 2641869 References: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientSharedPathCommittedMidPush3146650699/001/store/yi1ql4xzhdl35v4kqyzlbg3gg3508xdd-shared-dep1870 CA: text:sha256:1bmga105jbhbybk0vj97jqmh0nc6zvms0crp3vgwvys6dx0vzh251871--- PASS: TestClientSharedPathCommittedMidPush (12.06s)1872=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1873=== NAME TestClientMultipleUploads1874 client_integration_test.go:405: Created store path 1: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientMultipleUploads427340849/001/store/bph9wf777k5aqh74v1sv4671cgvy55s8-test-file-1.txt18752026/11/03 08:16:45 INFO Starting cleanup of old closures method=DELETE path=/api/closures18762026/11/03 08:16:45 INFO Garbage collection started1877=== NAME TestClientWithDependencies1878 client_integration_test.go:662: Found 1 dependencies (including self)1879=== NAME TestClientMultipleUploads1880 client_integration_test.go:405: Created store path 2: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientMultipleUploads427340849/001/store/6gjbjm9izj9m0n9134fn0270gib72l4i-test-file-2.txt18812026/11/03 08:16:45 INFO Aborted multipart uploads count=0 kept=018822026/11/03 08:16:45 WARN Force mode enabled - objects will be deleted immediately without grace period18832026/11/03 08:16:45 INFO Received push request method=POST path=/api/pushes18842026/11/03 08:16:45 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18852026/11/03 08:16:45 INFO Uploading bph9wf777k5aqh74v1sv4671cgvy55s8-test-file-1.txt (160B)18862026/11/03 08:16:45 INFO Uploading 6gjbjm9izj9m0n9134fn0270gib72l4i-test-file-2.txt (160B)18872026/11/03 08:16:45 INFO Uploading bv99az73g8shd8dcvlp53bln9zw85v5q-test-file-0.txt (160B)18882026/11/03 08:16:45 INFO Received push request method=POST path=/api/pushes18892026/11/03 08:16:45 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18902026/11/03 08:16:45 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18912026/11/03 08:16:45 WARN Failed to register uploaded object key=bph9wf777k5aqh74v1sv4671cgvy55s8.ls error="server returned 404: 404 page not found\n"18922026/11/03 08:16:45 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18932026/11/03 08:16:45 INFO Uploading 1qindxmzyvf2rzd4m6splk0pmg8n9yi2-test-script (136B)18942026/11/03 08:16:45 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18952026/11/03 08:16:45 WARN Failed to register uploaded object key=bv99az73g8shd8dcvlp53bln9zw85v5q.ls error="server returned 404: 404 page not found\n"18962026/11/03 08:16:45 WARN Failed to register uploaded object key=6gjbjm9izj9m0n9134fn0270gib72l4i.ls error="server returned 404: 404 page not found\n"18972026/11/03 08:16:45 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18982026/11/03 08:16:45 INFO Signed narinfos id=1 count=318992026/11/03 08:16:45 INFO Uploading 3 narinfos19002026/11/03 08:16:45 WARN Failed to register uploaded object key=1qindxmzyvf2rzd4m6splk0pmg8n9yi2.ls error="server returned 404: 404 page not found\n"19012026/11/03 08:16:45 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"19022026/11/03 08:16:45 WARN Failed to register uploaded object key=bph9wf777k5aqh74v1sv4671cgvy55s8.narinfo error="server returned 404: 404 page not found\n"19032026/11/03 08:16:45 WARN Failed to register uploaded object key=bv99az73g8shd8dcvlp53bln9zw85v5q.narinfo error="server returned 404: 404 page not found\n"19042026/11/03 08:16:45 INFO Received complete push request method=POST path=/api/pushes/1/complete19052026/11/03 08:16:45 WARN Failed to register uploaded object key=6gjbjm9izj9m0n9134fn0270gib72l4i.narinfo error="server returned 404: 404 page not found\n"19062026/11/03 08:16:45 WARN Failed to register uploaded object key=log/h6h3i3d8wxdvr2f8wb6xpl0xsw03y888-test-script.drv error="server returned 404: 404 page not found\n"19072026/11/03 08:16:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19082026/11/03 08:16:46 INFO Signed narinfos id=1 count=119092026/11/03 08:16:46 INFO Uploading 1 narinfos19102026/11/03 08:16:46 INFO Completed push id=1 objects=9 duration=49.909792ms19112026/11/03 08:16:46 INFO Upload complete. (574ms)1912 client_integration_test.go:416: Uploaded 3 paths in 709.264833ms19132026/11/03 08:16:46 INFO Received complete push request method=POST path=/api/pushes/1/complete19142026/11/03 08:16:46 WARN Failed to register uploaded object key=1qindxmzyvf2rzd4m6splk0pmg8n9yi2.narinfo error="server returned 404: 404 page not found\n"19152026/11/03 08:16:46 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=019162026/11/03 08:16:46 INFO Completed push id=1 objects=4 duration=43.895542ms19172026/11/03 08:16:46 INFO Upload complete. (675ms)1918=== NAME TestClientWithDependencies1919 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientWithDependencies2154866336/001/store) requires matching store prefix1920--- PASS: TestClientMultipleUploads (11.97s)1921=== CONT TestCacheConfigHandler/full_config,_no_issuer1922=== CONT TestCacheConfigHandler/no_signing_keys1923=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1924=== CONT TestCacheConfigHandler/no_cache_url_configured1925--- PASS: TestCacheConfigHandler (0.01s)1926 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1927 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1928 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1929 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1930=== CONT TestClientErrorHandling/InvalidStorePath19312026/11/03 08:16:46 INFO Vacuumed table table=pending_closures1932=== NAME TestClientIntegration1933 client_integration_test.go:291: Created store path: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientIntegration2914582654/002/store/wr4pcdrizclcxadxzhnvkbjx6jmfc6hi-test-file.txt19342026/11/03 08:16:46 INFO Vacuumed table table=pending_objects19352026/11/03 08:16:46 INFO Vacuumed table table=multipart_uploads19362026/11/03 08:16:46 INFO Vacuumed table table=closures1937--- PASS: TestClientWithDependencies (12.39s)1938=== CONT TestClientErrorHandling/ServerNotAvailable19392026/11/03 08:16:46 INFO Vacuumed table table=objects19402026/11/03 08:16:46 INFO Received push request method=POST path=/api/pushes19412026/11/03 08:16:46 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19422026/11/03 08:16:46 INFO Uploading wr4pcdrizclcxadxzhnvkbjx6jmfc6hi-test-file.txt (152B)19432026/11/03 08:16:46 WARN Failed to register uploaded object key=wr4pcdrizclcxadxzhnvkbjx6jmfc6hi.ls error="server returned 404: 404 page not found\n"19442026/11/03 08:16:46 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19452026/11/03 08:16:46 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"19462026/11/03 08:16:46 INFO Signed narinfos id=1 count=119472026/11/03 08:16:46 INFO Uploading 1 narinfos19482026/11/03 08:16:46 INFO Received complete push request method=POST path=/api/pushes/1/complete19492026/11/03 08:16:46 WARN Failed to register uploaded object key=wr4pcdrizclcxadxzhnvkbjx6jmfc6hi.narinfo error="server returned 404: 404 page not found\n"1950=== RUN TestService_RequireScope_OIDC/builder_may_write1951=== PAUSE TestService_RequireScope_OIDC/builder_may_write1952=== RUN TestService_RequireScope_OIDC/builder_may_not_admin19532026/11/03 08:16:46 INFO Completed push id=1 objects=3 duration=58.037209ms1954=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1955=== RUN TestService_RequireScope_OIDC/ops_may_admin1956=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1957=== RUN TestService_RequireScope_OIDC/ops_may_not_write1958=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1959=== RUN TestService_RequireScope_OIDC/reader_may_not_write1960=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1961=== RUN TestService_RequireScope_OIDC/static_token_may_admin1962=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1963=== RUN TestService_RequireScope_OIDC/static_token_may_write1964=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1965=== RUN TestService_RequireScope_OIDC/reader_may_read1966=== PAUSE TestService_RequireScope_OIDC/reader_may_read1967=== RUN TestService_RequireScope_OIDC/writer_implies_read1968=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1969=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1970=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1971=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1972=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc19732026/11/03 08:16:46 INFO Upload complete. (401ms)1974=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1975=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1976=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1977=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1978=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1979=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1980=== CONT TestClientErrorHandling/InvalidAuthToken19812026/11/03 08:16:46 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19822026/11/03 08:16:46 WARN Request failed, retrying attempt=2 backoff=207.437702ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19832026/11/03 08:16:46 INFO All 1 paths already cached1984=== NAME TestClientIntegration1985 client_integration_test.go:317: Retrieved narinfo from S3:1986 StorePath: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientIntegration2914582654/002/store/wr4pcdrizclcxadxzhnvkbjx6jmfc6hi-test-file.txt1987 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1988 Compression: zstd1989 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11990 NarSize: 1521991 References: 1992 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11993 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1994 client_integration_test.go:318: Decompressed .ls content (64 bytes):1995 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}19962026/11/03 08:16:47 WARN Request failed, retrying attempt=3 backoff=434.664362ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1997=== NAME TestClientCADerivations1998 client_ca_test.go:136: Built CA derivation: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientCADerivations2618673205/001/store/jh8fk0snbsmy7m9ay3i68i8h16b8fvdq-ca-test1999--- PASS: TestReadProxyConditionalGet (9.17s)2000=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2001=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20022026/11/03 08:16:47 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]2003=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2004=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20052026/11/03 08:16:47 WARN Authentication failed token_preview=eyJhbGciOi...vxhee2rmxQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2006=== CONT TestService_RequireScope_OIDC/builder_may_write2007--- PASS: TestService_AuthMiddleware_OIDC (9.93s)2008 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2009 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2010 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2011 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2012=== CONT TestService_RequireScope_OIDC/reader_may_read2013=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2014=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20152026/11/03 08:16:47 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]2016=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2017=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2018=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2019=== CONT TestService_RequireScope_OIDC/writer_implies_read2020=== CONT TestService_RequireScope_OIDC/reader_may_not_write2021=== CONT TestService_RequireScope_OIDC/static_token_may_write2022=== CONT TestService_RequireScope_OIDC/static_token_may_admin2023=== CONT TestService_RequireScope_OIDC/ops_may_admin2024=== CONT TestService_RequireScope_OIDC/ops_may_not_write2025=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2026=== NAME TestClientCADerivations2027 client_ca_test.go:139: Found 1 dependencies (including self)2028--- PASS: TestService_RequireScope_OIDC (11.16s)2029 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.01s)2030 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2031 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2032 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2033 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2034 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2035 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2036 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2037 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2038 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2039 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2040 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2041 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2042 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)20432026/11/03 08:16:47 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=020442026/11/03 08:16:47 INFO Received create pin request method=POST path=/api/pins/myapp20452026/11/03 08:16:47 INFO Created/updated pin name=myapp store_path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestPinProtectsFromGC2197426107/001/store/j0yrx344nqqbwpf508pldv3adcfqv84d-pinned-file.txt narinfo_key=j0yrx344nqqbwpf508pldv3adcfqv84d.narinfo20462026/11/03 08:16:47 INFO Starting cleanup of old closures method=DELETE path=/api/closures20472026/11/03 08:16:47 INFO Garbage collection started20482026/11/03 08:16:47 INFO Received push request method=POST path=/api/pushes20492026/11/03 08:16:47 INFO Aborted multipart uploads count=0 kept=020502026/11/03 08:16:47 INFO Object in database but missing from S3 key=wr4pcdrizclcxadxzhnvkbjx6jmfc6hi.ls20512026/11/03 08:16:47 WARN Found objects in DB but missing from S3, will re-upload count=120522026/11/03 08:16:47 WARN Force mode enabled - objects will be deleted immediately without grace period20532026/11/03 08:16:47 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20542026/11/03 08:16:47 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020552026/11/03 08:16:47 INFO Vacuumed table table=pending_closures20562026/11/03 08:16:47 INFO Vacuumed table table=pending_objects20572026/11/03 08:16:47 INFO Vacuumed table table=multipart_uploads20582026/11/03 08:16:47 INFO Vacuumed table table=closures20592026/11/03 08:16:47 INFO Vacuumed table table=objects2060--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (9.03s)20612026/11/03 08:16:47 INFO Received complete push request method=POST path=/api/pushes/2/complete20622026/11/03 08:16:47 WARN Failed to register uploaded object key=wr4pcdrizclcxadxzhnvkbjx6jmfc6hi.ls error="server returned 404: 404 page not found\n"20632026/11/03 08:16:47 WARN Request failed, retrying attempt=4 backoff=746.592793ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20642026/11/03 08:16:47 INFO Completed push id=2 objects=3 duration=6.21425ms20652026/11/03 08:16:47 INFO Upload complete. (276ms)2066=== NAME TestClientIntegration2067 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)2068 client_integration_test.go:335: Decompressed .ls content (49 bytes):2069 {"version":1,"root":{"type":"regular","size":39}}20702026/11/03 08:16:47 INFO Received push request method=POST path=/api/pushes20712026/11/03 08:16:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20722026/11/03 08:16:47 INFO Uploading jh8fk0snbsmy7m9ay3i68i8h16b8fvdq-ca-test (144B)20732026/11/03 08:16:47 WARN Failed to register uploaded object key=jh8fk0snbsmy7m9ay3i68i8h16b8fvdq.ls error="server returned 404: 404 page not found\n"20742026/11/03 08:16:47 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"20752026/11/03 08:16:47 WARN Failed to register uploaded object key=log/p566a2ldq42q9530vd2b5i66sqwj17x7-ca-test.drv error="server returned 404: 404 page not found\n"20762026/11/03 08:16:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20772026/11/03 08:16:47 INFO Signed narinfos id=1 count=120782026/11/03 08:16:47 INFO Uploading 1 narinfos20792026/11/03 08:16:47 INFO Received complete push request method=POST path=/api/pushes/1/complete20802026/11/03 08:16:47 WARN Failed to register uploaded object key=jh8fk0snbsmy7m9ay3i68i8h16b8fvdq.narinfo error="server returned 404: 404 page not found\n"20812026/11/03 08:16:47 INFO Completed push id=1 objects=4 duration=18.402417ms20822026/11/03 08:16:47 INFO Upload complete. (636ms)20832026/11/03 08:16:47 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20842026/11/03 08:16:47 WARN mTLS auth: bound subjects configured but subject DN unavailable20852026/11/03 08:16:47 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2086--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (9.48s)2087=== NAME TestClientCADerivations2088 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientCADerivations2618673205/001/store/jh8fk0snbsmy7m9ay3i68i8h16b8fvdq-ca-test2089 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2090 Compression: zstd2091 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2092 NarSize: 1442093 References: 2094 Deriver: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientCADerivations2618673205/001/store/p566a2ldq42q9530vd2b5i66sqwj17x7-ca-test.drv2095 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2096 client_ca_test.go:185: Checking for realisation files in S3...2097 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2098 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache20992026/11/03 08:16:48 INFO Received push request method=POST path=/api/pushes21002026/11/03 08:16:48 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)21012026/11/03 08:16:48 INFO Received complete push request method=POST path=/api/pushes/3/complete21022026/11/03 08:16:48 WARN Failed to register uploaded object key=wr4pcdrizclcxadxzhnvkbjx6jmfc6hi.ls error="server returned 404: 404 page not found\n"21032026/11/03 08:16:48 INFO Completed push id=3 objects=3 duration=1.624709ms21042026/11/03 08:16:48 INFO Upload complete. (128ms)2105 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket85?endpoint=http://localhost:50123®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestClientCADerivations2618673205/001/store'2106 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12107=== NAME TestClientIntegration2108 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)2109 client_integration_test.go:352: Decompressed .ls content (49 bytes):2110 {"version":1,"root":{"type":"regular","size":39}}2111 client_integration_test.go:363: Testing garbage collection...21122026/11/03 08:16:48 INFO Starting cleanup of old closures method=DELETE path=/api/closures21132026/11/03 08:16:48 INFO Garbage collection started2114--- PASS: TestService_ReadAuthMiddleware (9.69s)21152026/11/03 08:16:48 INFO Aborted multipart uploads count=0 kept=021162026/11/03 08:16:48 WARN Force mode enabled - objects will be deleted immediately without grace period2117--- PASS: TestClientCADerivations (12.63s)21182026/11/03 08:16:48 WARN Request failed, retrying attempt=5 backoff=1.468927737s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21192026/11/03 08:16:48 INFO Received uploads request method=POST path=/api/pending_closures21202026/11/03 08:16:48 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=021212026/11/03 08:16:48 INFO Aborted multipart uploads count=0 kept=021222026/11/03 08:16:48 WARN Force mode enabled - objects will be deleted immediately without grace period21232026/11/03 08:16:48 INFO Vacuumed table table=pending_closures21242026/11/03 08:16:48 INFO Vacuumed table table=pending_objects21252026/11/03 08:16:48 INFO Vacuumed table table=multipart_uploads21262026/11/03 08:16:48 INFO Vacuumed table table=closures21272026/11/03 08:16:48 INFO Vacuumed table table=objects21282026/11/03 08:16:48 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=1 objects-deleted-after-grace-period=1 objects-failed-to-delete=021292026/11/03 08:16:48 INFO Vacuumed table table=pending_closures21302026/11/03 08:16:48 INFO Vacuumed table table=pending_objects21312026/11/03 08:16:48 INFO Vacuumed table table=multipart_uploads21322026/11/03 08:16:48 INFO Vacuumed table table=closures21332026/11/03 08:16:48 INFO Received uploads request method=POST path=/api/pending_closures21342026/11/03 08:16:48 INFO Vacuumed table table=objects21352026/11/03 08:16:48 INFO Aborted multipart uploads count=0 kept=021362026/11/03 08:16:48 WARN Force mode enabled - objects will be deleted immediately without grace period21372026/11/03 08:16:48 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=021382026/11/03 08:16:48 INFO Vacuumed table table=pending_closures21392026/11/03 08:16:48 INFO Vacuumed table table=pending_objects21402026/11/03 08:16:48 INFO Vacuumed table table=multipart_uploads21412026/11/03 08:16:48 INFO Vacuumed table table=closures21422026/11/03 08:16:48 INFO Vacuumed table table=objects2143--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2144 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (9.95s)2145 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (9.62s)21462026/11/03 08:16:49 INFO Received uploads request method=POST path=/api/pending_closures2147=== NAME TestPinProtectsFromGC2148 client_integration_test.go:887: Pin successfully protected closure from garbage collection2149--- PASS: TestPinProtectsFromGC (17.06s)21502026/11/03 08:16:49 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21512026/11/03 08:16:49 WARN Request failed, retrying attempt=2 backoff=189.706074ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2152--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.01s)2153 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (9.64s)2154 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (10.02s)21552026/11/03 08:16:50 WARN Request failed, retrying attempt=3 backoff=430.060811ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21562026/11/03 08:16:50 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02157=== NAME TestClientIntegration2158 client_integration_test.go:370: Objects in database after GC:2159 client_integration_test.go:370: Successfully deleted all objects with GC --force2160--- PASS: TestClientIntegration (15.05s)21612026/11/03 08:16:50 INFO Received uploads request method=POST path=/api/pending_closures21622026/11/03 08:16:50 WARN Request failed, retrying attempt=4 backoff=758.812398ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21632026/11/03 08:16:51 WARN Request failed, retrying attempt=5 backoff=1.726911876s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21642026/11/03 08:16:51 INFO Received uploads request method=POST path=/api/pending_closures21652026/11/03 08:16:52 INFO Received uploads request method=POST path=/api/pending_closures21662026/11/03 08:16:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21672026/11/03 08:16:53 WARN Failed to fetch cache config, uploading without size limit error="fetching cache config: sending request: request failed after retries: Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused"21682026/11/03 08:16:53 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21692026/11/03 08:16:53 WARN Request failed, retrying attempt=2 backoff=207.978701ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21702026/11/03 08:16:53 WARN Request failed, retrying attempt=3 backoff=422.296513ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21712026/11/03 08:16:53 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLjY3NjlmMjY1LTUwZTctNDIzYS1hNmEyLWM3NWM3ZGFkMzY2OXgxNzkzNjkzODA5MjEzMjQxMDAw parts=1021722026/11/03 08:16:53 INFO Received uploads request method=POST path=/api/pending_closures21732026/11/03 08:16:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21742026/11/03 08:16:53 INFO Completed upload id=1 objects=3 duration=23.001333ms21752026/11/03 08:16:53 WARN Request failed, retrying attempt=4 backoff=768.240799ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21762026/11/03 08:16:54 WARN Request failed, retrying attempt=5 backoff=1.638001453s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21772026/11/03 08:16:54 INFO Received uploads request method=POST path=/api/pending_closures21782026/11/03 08:16:54 INFO Received uploads request method=POST path=/api/pending_closures21792026/11/03 08:16:54 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21802026/11/03 08:16:54 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21812026/11/03 08:16:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete2182--- PASS: TestPendingClosureWriteTimeout (0.01s)2183 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2184 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2185 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2186 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (11.13s)2187=== NAME TestOrphanedObjectsGCStressTest2188 orphaned_objects_gc_test.go:503: Stress test completed successfully:2189 orphaned_objects_gc_test.go:504: - Active objects preserved: 202190 orphaned_objects_gc_test.go:505: - Objects deleted: 2102191 orphaned_objects_gc_test.go:506: - Total GC'd: 2102192--- PASS: TestOrphanedObjectsGCStressTest (54.79s)21932026/11/03 08:16:55 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLmNlZWQ0ZGY2LTU0OTktNDZkYS05NDg1LTA4OWU4NDBhNDZhYngxNzkzNjkzODEwNTQ1MDUwMDAw parts=1021942026/11/03 08:16:55 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21952026/11/03 08:16:55 INFO Completed upload id=1 objects=3 duration=43.02ms21962026/11/03 08:16:55 INFO Received uploads request method=POST path=/api/pending_closures21972026/11/03 08:16:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21982026/11/03 08:16:56 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21992026/11/03 08:16:56 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLjMwZDFjMjQwLWVjOTktNDBlYi1iYjY5LWNkMGY4MmMwNjRlNHgxNzkzNjkzODExNDMwMTA5MDAw parts=1022002026/11/03 08:16:56 WARN Request failed, retrying attempt=2 backoff=182.800084ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22012026/11/03 08:16:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22022026/11/03 08:16:56 INFO Aborted multipart uploads count=0 kept=022032026/11/03 08:16:56 WARN Force mode enabled - objects will be deleted immediately without grace period22042026-11-03 08:16:56.440 UTC [27574] ERROR: canceling statement due to user request22052026-11-03 08:16:56.440 UTC [27574] STATEMENT: -- name: MarkStaleObjects :execrows2206 WITH RECURSIVE ct AS (2207 SELECT timezone('UTC', now()) AS now2208 ),2209 closure_reach AS (2210 -- Start with all closure keys2211 SELECT o.key, o.refs2212 FROM objects o2213 INNER JOIN closures c ON o.key = c.key2214 UNION2215 -- Recursively add all referenced objects2216 SELECT o.key, o.refs2217 FROM objects o2218 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2219 ),2220 reachable_objects AS (2221 SELECT DISTINCT key FROM closure_reach2222 ),2223 stale_objects AS (2224 SELECT o.key2225 FROM objects AS o, ct2226 WHERE2227 NOT EXISTS (2228 SELECT 12229 FROM reachable_objects ro2230 WHERE ro.key = o.key2231 )2232 AND NOT EXISTS (2233 SELECT 12234 FROM pending_objects AS po2235 WHERE po.key = o.key2236 )2237 AND o.deleted_at IS NULL -- Only mark fresh objects2238 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2239 FOR UPDATE2240 )2241 UPDATE objects2242 SET2243 deleted_at = ct.now,2244 first_deleted_at = COALESCE(first_deleted_at, ct.now)2245 FROM stale_objects, ct2246 WHERE objects.key = stale_objects.key2247 22482026/11/03 08:16:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22492026/11/03 08:16:56 INFO Completed upload id=1 objects=3 duration=26.022833ms22502026/11/03 08:16:56 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLjZhMmRjOTc2LTRjYWItNDVmNy04YTUxLTdiYWI3MzJlMjMzZngxNzkzNjkzODEyMzI5NTQyMDAw parts=1022512026/11/03 08:16:56 WARN Request failed, retrying attempt=3 backoff=369.864786ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22522026/11/03 08:16:56 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22532026/11/03 08:16:56 INFO Completed upload id=1 objects=3 duration=22.549084ms22542026/11/03 08:16:56 INFO Received uploads request method=POST path=/api/pending_closures22552026/11/03 08:16:56 INFO Aborted multipart uploads count=0 kept=022562026/11/03 08:16:56 WARN Force mode enabled - objects will be deleted immediately without grace period22572026/11/03 08:16:56 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:50123/bucket103/?delete=\": context canceled"2258--- PASS: TestGCEndsOnShutdown (0.01s)2259 --- PASS: TestGCEndsOnShutdown/before_the_run (10.75s)2260 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (11.36s)2261 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (11.64s)22622026/11/03 08:16:56 WARN Request failed, retrying attempt=4 backoff=755.442869ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22632026/11/03 08:16:57 INFO Received uploads request method=POST path=/api/pending_closures22642026/11/03 08:16:57 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22652026/11/03 08:16:57 WARN Found objects in DB but missing from S3, will re-upload count=122662026/11/03 08:16:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22672026/11/03 08:16:57 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLjU4Mjk2YzcyLWQzMmUtNGE0ZS05ZWNhLTYwZTUxMTBkYWI2ZHgxNzkzNjkzODEzNjEyMTgwMDAw parts=1022682026/11/03 08:16:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22692026/11/03 08:16:57 INFO Completed upload id=1 objects=3 duration=14.135958ms22702026/11/03 08:16:57 INFO Received uploads request method=POST path=/api/pending_closures22712026/11/03 08:16:57 WARN Request failed, retrying attempt=5 backoff=1.688897711s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22722026/11/03 08:16:57 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22732026/11/03 08:16:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22742026/11/03 08:16:57 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22752026/11/03 08:16:58 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLjM1YTY1YWRkLTE1OWEtNDRmOS1iMWRlLTE2ZjUzODhhYjI0OXgxNzkzNjkzODE1OTc3NjI3MDAw parts=1022762026/11/03 08:16:58 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22772026/11/03 08:16:58 INFO Completed upload id=2 objects=3 duration=1.367083ms22782026/11/03 08:16:58 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22792026/11/03 08:16:58 INFO Received uploads request method=POST path=/api/pending_closures22802026/11/03 08:16:58 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22812026/11/03 08:16:58 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo22822026/11/03 08:16:58 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=ZjAzNGU4YWYtYjM1OC00NTcyLTk0NGQtODk4ZDRhZWFhNzAxLjljY2QxZTgxLThmNzAtNGQwYy04YTM2LTI3OTJhM2Q0YzRkMXgxNzkzNjkzODE2NjczODQzMDAw parts=1022832026/11/03 08:16:58 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22842026/11/03 08:16:58 INFO Completed upload id=2 objects=3 duration=1.347042ms22852026/11/03 08:16:58 INFO Received uploads request method=POST path=/api/pending_closures22862026/11/03 08:16:58 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22872026/11/03 08:16:58 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo2288--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.00s)2289 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (14.76s)2290 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (15.49s)2291 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (15.23s)2292 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (16.82s)2293 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (17.51s)2294--- PASS: TestClientErrorHandling (0.00s)2295 --- PASS: TestClientErrorHandling/InvalidStorePath (11.02s)2296 --- PASS: TestClientErrorHandling/InvalidAuthToken (11.45s)2297 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.19s)2298PASS2299{"timestamp":"2026-11-03T08:16:59.459038Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:50749","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}2300{"timestamp":"2026-11-03T08:16:59.459184Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:50613","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(4)"}23012026-11-03 08:16:59.678 UTC [23114] LOG: received smart shutdown request23022026-11-03 08:16:59.680 UTC [23114] LOG: background worker "logical replication launcher" (PID 23132) exited with exit code 123032026-11-03 08:16:59.711 UTC [23125] LOG: shutting down23042026-11-03 08:16:59.712 UTC [23125] LOG: checkpoint starting: shutdown immediate23052026-11-03 08:17:01.820 UTC [23125] LOG: checkpoint complete: wrote 12079 buffers (73.7%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=1.137 s, sync=0.921 s, total=2.109 s; sync files=35730, longest=0.016 s, average=0.001 s; distance=525263 kB, estimate=525263 kB; lsn=0/21880E88, redo lsn=0/21880E8823062026-11-03 08:17:01.831 UTC [23114] LOG: database system is shut down2307Running OIDC tests...2308=== RUN TestAudienceForIssuer2309=== PAUSE TestAudienceForIssuer2310=== RUN TestGlobMatch2311=== PAUSE TestGlobMatch2312=== RUN TestValidateToken_ValidToken2313=== PAUSE TestValidateToken_ValidToken2314=== RUN TestValidateToken_WrongAudience2315=== PAUSE TestValidateToken_WrongAudience2316=== RUN TestValidateToken_Expired2317=== PAUSE TestValidateToken_Expired2318=== RUN TestValidateToken_BoundClaimsMismatch2319=== PAUSE TestValidateToken_BoundClaimsMismatch2320=== RUN TestValidateToken_BoundSubjectMismatch2321=== PAUSE TestValidateToken_BoundSubjectMismatch2322=== RUN TestValidateToken_MultipleProviders2323=== PAUSE TestValidateToken_MultipleProviders2324=== RUN TestValidateToken_NoMatchingProvider2325=== PAUSE TestValidateToken_NoMatchingProvider2326=== RUN TestValidateToken_KubernetesServiceAccount2327=== PAUSE TestValidateToken_KubernetesServiceAccount2328=== RUN TestNewValidator_KubernetesRequiresCA2329=== PAUSE TestNewValidator_KubernetesRequiresCA2330=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2331=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2332=== RUN TestPins_ReservedForMatchingRule2333=== PAUSE TestPins_ReservedForMatchingRule2334=== RUN TestPins_TopLevelShorthand2335=== PAUSE TestPins_TopLevelShorthand2336=== RUN TestPins_ConfigValidation2337=== PAUSE TestPins_ConfigValidation2338=== RUN TestScopes_LegacyProviderDefaultsToWrite2339=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2340=== RUN TestScopes_Rules2341=== PAUSE TestScopes_Rules2342=== RUN TestScopes_ConfigValidation2343=== PAUSE TestScopes_ConfigValidation2344=== CONT TestAudienceForIssuer2345--- PASS: TestAudienceForIssuer (0.00s)2346=== CONT TestValidateToken_NoMatchingProvider2347=== CONT TestPins_ConfigValidation2348=== CONT TestScopes_LegacyProviderDefaultsToWrite2349=== CONT TestScopes_Rules2350=== CONT TestValidateToken_KubernetesServiceAccount2351=== CONT TestPins_TopLevelShorthand2352--- PASS: TestPins_ConfigValidation (0.00s)2353=== CONT TestPins_ReservedForMatchingRule2354=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2355=== CONT TestNewValidator_KubernetesRequiresCA2356=== CONT TestValidateToken_Expired2357=== CONT TestValidateToken_MultipleProviders2358=== CONT TestValidateToken_BoundSubjectMismatch2359=== CONT TestValidateToken_BoundClaimsMismatch2360=== CONT TestValidateToken_ValidToken2361=== CONT TestValidateToken_WrongAudience2362=== CONT TestScopes_ConfigValidation2363--- PASS: TestScopes_ConfigValidation (0.00s)2364=== CONT TestGlobMatch2365=== RUN TestGlobMatch/foo_foo2366=== PAUSE TestGlobMatch/foo_foo2367=== RUN TestGlobMatch/foo_bar2368=== PAUSE TestGlobMatch/foo_bar2369=== RUN TestGlobMatch/*_2370=== PAUSE TestGlobMatch/*_2371=== RUN TestGlobMatch/*_anything2372=== PAUSE TestGlobMatch/*_anything2373=== RUN TestGlobMatch/foo*_foo2374=== PAUSE TestGlobMatch/foo*_foo2375=== RUN TestGlobMatch/foo*_foobar2376=== PAUSE TestGlobMatch/foo*_foobar2377=== RUN TestGlobMatch/foo*_bar2378=== PAUSE TestGlobMatch/foo*_bar2379=== RUN TestGlobMatch/*bar_bar2380=== PAUSE TestGlobMatch/*bar_bar2381=== RUN TestGlobMatch/*bar_foobar2382=== PAUSE TestGlobMatch/*bar_foobar2383=== RUN TestGlobMatch/*bar_foo2384=== PAUSE TestGlobMatch/*bar_foo2385=== RUN TestGlobMatch/foo*bar_foobar2386=== PAUSE TestGlobMatch/foo*bar_foobar2387=== RUN TestGlobMatch/foo*bar_foo123bar2388=== PAUSE TestGlobMatch/foo*bar_foo123bar2389=== RUN TestGlobMatch/foo*bar_foobarbaz2390=== PAUSE TestGlobMatch/foo*bar_foobarbaz2391=== RUN TestGlobMatch/*/*_foo/bar2392=== PAUSE TestGlobMatch/*/*_foo/bar2393=== RUN TestGlobMatch/*/*_foo2394=== PAUSE TestGlobMatch/*/*_foo2395=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2396=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2397=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02398=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02399=== RUN TestGlobMatch/refs/*/main_refs/heads/main2400=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2401=== RUN TestGlobMatch/fo?_foo2402=== PAUSE TestGlobMatch/fo?_foo2403=== RUN TestGlobMatch/fo?_fo2404=== PAUSE TestGlobMatch/fo?_fo2405=== RUN TestGlobMatch/fo?_fooo2406=== PAUSE TestGlobMatch/fo?_fooo2407=== RUN TestGlobMatch/?oo_foo2408=== PAUSE TestGlobMatch/?oo_foo2409=== RUN TestGlobMatch/?oo_boo2410=== PAUSE TestGlobMatch/?oo_boo2411=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2412=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2413=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2414=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2415=== CONT TestGlobMatch/foo_foo2416=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2417=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2418=== CONT TestGlobMatch/?oo_boo2419=== CONT TestGlobMatch/?oo_foo2420=== CONT TestGlobMatch/fo?_fooo2421=== CONT TestGlobMatch/fo?_fo2422=== CONT TestGlobMatch/fo?_foo2423=== CONT TestGlobMatch/refs/*/main_refs/heads/main2424=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02425=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2426=== CONT TestGlobMatch/*/*_foo2427=== CONT TestGlobMatch/*/*_foo/bar2428=== CONT TestGlobMatch/foo*bar_foobarbaz2429=== CONT TestGlobMatch/foo*bar_foo123bar2430=== CONT TestGlobMatch/foo*bar_foobar2431=== CONT TestGlobMatch/*bar_foo2432=== CONT TestGlobMatch/*bar_foobar2433=== CONT TestGlobMatch/*bar_bar2434=== CONT TestGlobMatch/foo*_bar2435=== CONT TestGlobMatch/foo*_foobar2436=== CONT TestGlobMatch/foo*_foo2437=== CONT TestGlobMatch/*_anything2438=== CONT TestGlobMatch/*_2439=== CONT TestGlobMatch/foo_bar2440--- PASS: TestGlobMatch (0.00s)2441 --- PASS: TestGlobMatch/foo_foo (0.00s)2442 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2443 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2444 --- PASS: TestGlobMatch/?oo_boo (0.00s)2445 --- PASS: TestGlobMatch/?oo_foo (0.00s)2446 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2447 --- PASS: TestGlobMatch/fo?_fo (0.00s)2448 --- PASS: TestGlobMatch/fo?_foo (0.00s)2449 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2450 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2451 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2452 --- PASS: TestGlobMatch/*/*_foo (0.00s)2453 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2454 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2455 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2456 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2457 --- PASS: TestGlobMatch/*bar_foo (0.00s)2458 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2459 --- PASS: TestGlobMatch/*bar_bar (0.00s)2460 --- PASS: TestGlobMatch/foo*_bar (0.00s)2461 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2462 --- PASS: TestGlobMatch/foo*_foo (0.00s)2463 --- PASS: TestGlobMatch/*_anything (0.00s)2464 --- PASS: TestGlobMatch/*_ (0.00s)2465 --- PASS: TestGlobMatch/foo_bar (0.00s)24662026/11/03 08:17:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50754/oidc2467--- PASS: TestPins_ReservedForMatchingRule (0.07s)24682026/11/03 08:17:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50752/oidc24692026/11/03 08:17:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50756/oidc2470--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.08s)24712026/11/03 08:17:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50759/oidc2472--- PASS: TestValidateToken_ValidToken (0.05s)2473--- PASS: TestScopes_Rules (0.09s)24742026/11/03 08:17:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50758/oidc24752026/11/03 08:17:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50765/oidc2476--- PASS: TestValidateToken_BoundSubjectMismatch (0.08s)2477--- PASS: TestValidateToken_BoundClaimsMismatch (0.08s)24782026/11/03 08:17:04 http: TLS handshake error from 127.0.0.1:50763: read tcp 127.0.0.1:50762->127.0.0.1:50763: use of closed network connection2479--- PASS: TestNewValidator_KubernetesRequiresCA (0.10s)24802026/11/03 08:17:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50768/oidc2481--- PASS: TestValidateToken_WrongAudience (0.08s)24822026/11/03 08:17:04 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:50770/oidc24832026/11/03 08:17:04 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:50767/oidc2484--- PASS: TestValidateToken_MultipleProviders (0.10s)24852026/11/03 08:17:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50773/oidc2486--- PASS: TestPins_TopLevelShorthand (0.16s)24872026/11/03 08:17:04 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:507752488--- PASS: TestValidateToken_KubernetesServiceAccount (0.16s)24892026/11/03 08:17:04 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:50777/oidc24902026/11/03 08:17:04 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232491--- PASS: TestValidateToken_Expired (0.15s)2492--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.16s)24932026/11/03 08:17:04 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:50761/oidc2494--- PASS: TestValidateToken_NoMatchingProvider (0.18s)2495PASS2496Running hook tests...2497=== RUN TestSendPathsEmpty2498=== PAUSE TestSendPathsEmpty2499=== RUN TestQueueEnqueueAndFetch2500=== PAUSE TestQueueEnqueueAndFetch2501=== RUN TestQueueDeduplication2502=== PAUSE TestQueueDeduplication2503=== RUN TestQueueRemove2504=== PAUSE TestQueueRemove2505=== RUN TestQueueFetchBatchLimit2506=== PAUSE TestQueueFetchBatchLimit2507=== RUN TestQueueRetryMovesToBack2508=== PAUSE TestQueueRetryMovesToBack2509=== RUN TestQueueFetchRemoveLifecycle2510=== PAUSE TestQueueFetchRemoveLifecycle2511=== RUN TestQueueConcurrentWriters2512=== PAUSE TestQueueConcurrentWriters2513=== RUN TestQueueRemoveLargeClosure2514=== PAUSE TestQueueRemoveLargeClosure2515=== RUN TestServerClientIntegration2516--- PASS: TestServerClientIntegration (0.00s)2517=== RUN TestServerQueueError25182026/11/03 08:17:04 ERROR Failed to queue paths error="permission denied" count=12519--- PASS: TestServerQueueError (0.00s)2520=== RUN TestGetListenerSocketActivation2521 server_test.go:145: systemd socket activation does not exist on darwin2522--- SKIP: TestGetListenerSocketActivation (0.00s)2523=== RUN TestServerStalledClientDoesNotBlockShutdown2524=== PAUSE TestServerStalledClientDoesNotBlockShutdown2525=== RUN TestServerBacksOffOnAcceptErrors2526=== PAUSE TestServerBacksOffOnAcceptErrors2527=== RUN TestDrainIsolatesPoisonPath2528=== PAUSE TestDrainIsolatesPoisonPath2529=== RUN TestRunNotBlockedByPoisonHead2530=== PAUSE TestRunNotBlockedByPoisonHead2531=== RUN TestDrainGivesUpWhenServerDown2532=== PAUSE TestDrainGivesUpWhenServerDown2533=== RUN TestFailedPathPrunedByLaterClosure2534=== PAUSE TestFailedPathPrunedByLaterClosure2535=== RUN TestWorkerUploadsAndRemoves2536=== PAUSE TestWorkerUploadsAndRemoves2537=== RUN TestWorkerSkipsGCdPaths2538=== PAUSE TestWorkerSkipsGCdPaths2539=== RUN TestWorkerPrunesClosureDeps2540=== PAUSE TestWorkerPrunesClosureDeps2541=== RUN TestDrainTimeout2542=== PAUSE TestDrainTimeout2543=== RUN TestWorkerRemoveFailureIsNotProgress2544=== PAUSE TestWorkerRemoveFailureIsNotProgress2545=== RUN TestWorkerKeepsPathItCannotStat2546=== PAUSE TestWorkerKeepsPathItCannotStat2547=== CONT TestSendPathsEmpty2548=== CONT TestFailedPathPrunedByLaterClosure2549--- PASS: TestSendPathsEmpty (0.00s)2550=== CONT TestWorkerKeepsPathItCannotStat2551=== CONT TestWorkerRemoveFailureIsNotProgress2552=== CONT TestDrainTimeout2553=== CONT TestWorkerPrunesClosureDeps2554=== CONT TestWorkerSkipsGCdPaths2555=== CONT TestWorkerUploadsAndRemoves2556=== CONT TestDrainIsolatesPoisonPath2557=== CONT TestServerBacksOffOnAcceptErrors25582026/11/03 08:17:04 ERROR Accept failed error="too many open files"2559=== CONT TestServerStalledClientDoesNotBlockShutdown2560=== CONT TestQueueRemoveLargeClosure2561=== CONT TestDrainGivesUpWhenServerDown2562=== CONT TestQueueConcurrentWriters2563=== CONT TestQueueRemove2564=== CONT TestQueueFetchBatchLimit2565=== CONT TestQueueDeduplication2566=== CONT TestQueueFetchRemoveLifecycle2567=== CONT TestQueueEnqueueAndFetch2568=== CONT TestQueueRetryMovesToBack2569=== CONT TestRunNotBlockedByPoisonHead25702026/11/03 08:17:04 ERROR Accept failed error="too many open files"25712026/11/03 08:17:04 WARN Cannot stat store path, will retry later path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestWorkerKeepsPathItCannotStat770822571/002/locked/aaa error="stat /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestWorkerKeepsPathItCannotStat770822571/002/locked/aaa: permission denied"25722026/11/03 08:17:04 INFO Upload queue status pending=225732026/11/03 08:17:04 INFO Uploading batch count=22574--- PASS: TestQueueFetchBatchLimit (0.01s)2575--- PASS: TestQueueRetryMovesToBack (0.01s)25762026/11/03 08:17:04 INFO Uploading batch count=125772026/11/03 08:17:04 ERROR Upload failed error="upload failed" count=12578--- PASS: TestQueueDeduplication (0.01s)25792026/11/03 08:17:04 INFO Uploading batch count=125802026/11/03 08:17:04 INFO Upload queue status pending=225812026/11/03 08:17:04 WARN Cannot stat store path, will retry later path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestWorkerKeepsPathItCannotStat770822571/002/locked/aaa error="stat /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestWorkerKeepsPathItCannotStat770822571/002/locked/aaa: permission denied"25822026/11/03 08:17:04 INFO Upload queue status pending=325832026/11/03 08:17:04 INFO Uploading batch count=125842026/11/03 08:17:04 ERROR Upload failed error="upload failed" count=125852026/11/03 08:17:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestWorkerSkipsGCdPaths2563307937/002/nonexistent2586--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25872026/11/03 08:17:04 INFO Uploading batch count=425882026/11/03 08:17:04 ERROR Upload failed error="upload failed" count=425892026/11/03 08:17:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestDrainIsolatesPoisonPath496313914/002/bbb25902026/11/03 08:17:04 INFO Uploading batch count=225912026/11/03 08:17:04 INFO Upload queue status pending=225922026/11/03 08:17:04 INFO Uploading batch count=125932026/11/03 08:17:04 INFO Uploading batch count=125942026/11/03 08:17:04 INFO Uploading batch count=125952026/11/03 08:17:04 INFO Uploading batch count=125962026/11/03 08:17:04 ERROR Upload failed error="upload failed" count=125972026/11/03 08:17:04 INFO Uploading batch count=125982026/11/03 08:17:04 ERROR Upload failed error="upload failed" count=12599--- PASS: TestQueueEnqueueAndFetch (0.01s)2600--- PASS: TestQueueRemove (0.01s)26012026/11/03 08:17:04 WARN Cannot stat store path, will retry later path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestWorkerKeepsPathItCannotStat770822571/002/locked/aaa error="stat /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestWorkerKeepsPathItCannotStat770822571/002/locked/aaa: permission denied"26022026/11/03 08:17:04 INFO Uploading batch count=126032026/11/03 08:17:04 ERROR Upload failed error="upload failed" count=126042026/11/03 08:17:04 ERROR Drain finished with paths left in queue remaining=126052026/11/03 08:17:04 ERROR Drain finished with paths left in queue remaining=126062026/11/03 08:17:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestWorkerRemoveFailureIsNotProgress2113085746/002/nonexistent26072026/11/03 08:17:04 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126082026/11/03 08:17:04 INFO Uploading batch count=226092026/11/03 08:17:04 ERROR Upload failed error="upload failed" count=226102026/11/03 08:17:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestDrainGivesUpWhenServerDown3709644195/002/a26112026/11/03 08:17:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestWorkerRemoveFailureIsNotProgress2113085746/002/nonexistent26122026/11/03 08:17:04 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126132026/11/03 08:17:04 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestWorkerRemoveFailureIsNotProgress2113085746/002/nonexistent26142026/11/03 08:17:04 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126152026/11/03 08:17:04 ERROR Drain finished with paths left in queue remaining=12616--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)26172026/11/03 08:17:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestDrainGivesUpWhenServerDown3709644195/002/b26182026/11/03 08:17:04 ERROR Accept failed error="too many open files"26192026/11/03 08:17:04 INFO Uploading batch count=226202026/11/03 08:17:04 ERROR Upload failed error="upload failed" count=226212026/11/03 08:17:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestDrainGivesUpWhenServerDown3709644195/002/c26222026/11/03 08:17:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestDrainGivesUpWhenServerDown3709644195/002/d26232026/11/03 08:17:04 INFO Uploading batch count=226242026/11/03 08:17:04 ERROR Upload failed error="upload failed" count=226252026/11/03 08:17:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestDrainGivesUpWhenServerDown3709644195/002/e2626--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)26272026/11/03 08:17:04 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestDrainGivesUpWhenServerDown3709644195/002/f26282026/11/03 08:17:04 ERROR Drain finished with paths left in queue remaining=102629--- PASS: TestDrainIsolatesPoisonPath (0.02s)2630--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2631--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2632--- PASS: TestWorkerUploadsAndRemoves (0.03s)2633--- PASS: TestWorkerSkipsGCdPaths (0.03s)2634--- PASS: TestWorkerPrunesClosureDeps (0.03s)26352026/11/03 08:17:04 ERROR Accept failed error="too many open files"2636--- PASS: TestQueueRemoveLargeClosure (0.04s)2637--- PASS: TestQueueConcurrentWriters (0.04s)26382026/11/03 08:17:04 ERROR Accept failed error="too many open files"26392026/11/03 08:17:04 ERROR Accept failed error="too many open files"26402026/11/03 08:17:04 ERROR Failed to decode request error="read unix /private/var/tb/3/scratch/5f72cc1e653f715f/build/hook228245488/test.sock->: i/o timeout"26412026/11/03 08:17:04 ERROR Failed to write response error="write unix /private/var/tb/3/scratch/5f72cc1e653f715f/build/hook228245488/test.sock->: i/o timeout"2642--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26432026/11/03 08:17:05 ERROR Upload failed error="context deadline exceeded" count=226442026/11/03 08:17:05 ERROR Drain finished with paths left in queue remaining=42645--- PASS: TestDrainTimeout (0.22s)26462026/11/03 08:17:05 ERROR Accept failed error="too many open files"26472026/11/03 08:17:05 ERROR Accept failed error="too many open files"2648--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26492026/11/03 08:17:05 INFO Uploading batch count=126502026/11/03 08:17:05 INFO Uploading batch count=126512026/11/03 08:17:05 INFO Uploading batch count=126522026/11/03 08:17:05 ERROR Upload failed error="upload failed" count=126532026/11/03 08:17:05 INFO Uploading batch count=126542026/11/03 08:17:05 ERROR Upload failed error="upload failed" count=126552026/11/03 08:17:05 INFO Uploading batch count=126562026/11/03 08:17:05 ERROR Upload failed error="upload failed" count=126572026/11/03 08:17:05 INFO Uploading batch count=126582026/11/03 08:17:05 ERROR Upload failed error="upload failed" count=126592026/11/03 08:17:05 ERROR Drain finished with paths left in queue remaining=12660--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2661PASS2662Running signing tests...2663=== RUN TestExternalSigner2664=== PAUSE TestExternalSigner2665=== RUN TestExternalSignerWrongPublicKey2666=== PAUSE TestExternalSignerWrongPublicKey2667=== RUN TestExternalSignerErrors2668=== PAUSE TestExternalSignerErrors2669=== RUN TestExternalSignerRestartsAfterCrash2670=== PAUSE TestExternalSignerRestartsAfterCrash2671=== RUN TestExternalSignerProgramErrorKeepsProcess2672=== PAUSE TestExternalSignerProgramErrorKeepsProcess2673=== RUN TestExternalSignerClose2674=== PAUSE TestExternalSignerClose2675=== RUN TestExternalSignerRejectsInvalidPublicKey2676=== PAUSE TestExternalSignerRejectsInvalidPublicKey2677=== RUN TestExternalSignerCancellation2678=== PAUSE TestExternalSignerCancellation2679=== RUN TestGenerateFingerprint2680=== PAUSE TestGenerateFingerprint2681=== RUN TestParseSigningKey2682=== PAUSE TestParseSigningKey2683=== RUN TestSign2684=== PAUSE TestSign2685=== RUN TestSignBatch2686=== PAUSE TestSignBatch2687=== RUN TestNilKeyPublicKey2688=== PAUSE TestNilKeyPublicKey2689=== RUN TestSignErrors2690=== PAUSE TestSignErrors2691=== CONT TestExternalSigner2692=== CONT TestExternalSignerCancellation2693=== CONT TestExternalSignerRestartsAfterCrash2694=== CONT TestExternalSignerErrors2695=== CONT TestExternalSignerProgramErrorKeepsProcess2696=== CONT TestExternalSignerRejectsInvalidPublicKey2697=== RUN TestExternalSignerRejectsInvalidPublicKey/#002698=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002699=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2700=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2701=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2702=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2703=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2704=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2705=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2706=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2707=== CONT TestExternalSignerRejectsInvalidPublicKey/#002708=== CONT TestExternalSignerClose2709=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2710=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2711=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2712=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2713--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2714 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2715 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2716 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2717 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2718 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2719=== CONT TestExternalSignerWrongPublicKey2720=== CONT TestSignBatch2721=== CONT TestSignErrors2722=== CONT TestNilKeyPublicKey2723--- PASS: TestNilKeyPublicKey (0.00s)2724=== CONT TestParseSigningKey2725=== RUN TestParseSigningKey/valid_32-byte_key2726=== CONT TestSign2727=== CONT TestGenerateFingerprint2728=== RUN TestGenerateFingerprint/basic_with_references2729=== PAUSE TestGenerateFingerprint/basic_with_references2730=== RUN TestExternalSignerErrors/too_few_signatures2731=== PAUSE TestExternalSignerErrors/too_few_signatures2732=== PAUSE TestParseSigningKey/valid_32-byte_key2733=== RUN TestExternalSignerErrors/missing_signature_name2734=== PAUSE TestExternalSignerErrors/missing_signature_name2735=== RUN TestExternalSignerErrors/invalid_signature_base642736=== PAUSE TestExternalSignerErrors/invalid_signature_base642737=== RUN TestExternalSignerErrors/wrong_signature_length2738=== PAUSE TestExternalSignerErrors/wrong_signature_length2739=== RUN TestExternalSignerErrors/wrong_signatures_shape2740=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2741=== RUN TestExternalSignerErrors/program_error2742=== PAUSE TestExternalSignerErrors/program_error2743=== RUN TestExternalSignerErrors/exit_at_startup2744=== PAUSE TestExternalSignerErrors/exit_at_startup2745=== RUN TestExternalSignerErrors/wrong_id2746=== PAUSE TestExternalSignerErrors/wrong_id2747=== RUN TestExternalSignerErrors/unrequested_key2748=== PAUSE TestExternalSignerErrors/unrequested_key2749=== RUN TestExternalSignerErrors/wrong_signature_name2750=== PAUSE TestExternalSignerErrors/wrong_signature_name2751=== RUN TestExternalSignerErrors/invalid_JSON2752=== PAUSE TestExternalSignerErrors/invalid_JSON2753=== RUN TestExternalSignerErrors/null2754=== PAUSE TestExternalSignerErrors/null2755=== RUN TestExternalSignerErrors/missing_signatures2756=== PAUSE TestExternalSignerErrors/missing_signatures2757=== RUN TestExternalSignerErrors/null_signatures2758=== PAUSE TestExternalSignerErrors/null_signatures2759=== RUN TestExternalSignerErrors/exit_on_request2760=== PAUSE TestExternalSignerErrors/exit_on_request2761=== RUN TestGenerateFingerprint/no_references2762=== PAUSE TestGenerateFingerprint/no_references2763=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2764=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2765=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2766=== RUN TestParseSigningKey/no_colon2767=== PAUSE TestParseSigningKey/no_colon2768=== RUN TestParseSigningKey/empty_name2769=== PAUSE TestParseSigningKey/empty_name2770=== RUN TestParseSigningKey/invalid_base642771=== PAUSE TestParseSigningKey/invalid_base642772=== RUN TestExternalSignerErrors/wrong_shape2773=== PAUSE TestExternalSignerErrors/wrong_shape2774=== CONT TestExternalSignerErrors/too_few_signatures2775=== CONT TestExternalSignerErrors/wrong_signature_name2776=== CONT TestExternalSignerErrors/program_error2777=== CONT TestExternalSignerErrors/invalid_signature_base642778=== CONT TestExternalSignerErrors/unrequested_key2779=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2780=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2781=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2782=== RUN TestGenerateFingerprint/invalid_nar_hash_length2783=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2784=== RUN TestGenerateFingerprint/invalid_store_path_prefix2785=== CONT TestExternalSignerErrors/wrong_signature_length2786=== CONT TestExternalSignerErrors/wrong_shape2787=== CONT TestExternalSignerErrors/wrong_id2788=== CONT TestExternalSignerErrors/exit_on_request2789=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2790=== RUN TestGenerateFingerprint/invalid_reference_prefix2791=== RUN TestParseSigningKey/wrong_length2792=== PAUSE TestParseSigningKey/wrong_length2793=== CONT TestExternalSignerErrors/missing_signature_name2794=== CONT TestExternalSignerErrors/exit_at_startup2795--- PASS: TestSign (0.00s)2796=== CONT TestExternalSignerErrors/missing_signatures2797--- PASS: TestSignBatch (0.00s)2798=== CONT TestExternalSignerErrors/invalid_JSON2799=== CONT TestExternalSignerErrors/wrong_signatures_shape2800=== CONT TestExternalSignerErrors/null2801=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2802=== CONT TestExternalSignerErrors/null_signatures2803=== CONT TestParseSigningKey/valid_32-byte_key2804=== CONT TestParseSigningKey/invalid_base642805=== CONT TestParseSigningKey/wrong_length2806=== CONT TestParseSigningKey/no_colon2807=== RUN TestSignErrors/nil_key2808=== PAUSE TestSignErrors/nil_key2809=== CONT TestParseSigningKey/empty_name2810=== RUN TestSignErrors/nil_narinfo2811=== PAUSE TestSignErrors/nil_narinfo2812=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2813=== RUN TestSignErrors/invalid_narinfo2814--- PASS: TestParseSigningKey (0.00s)2815 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2816 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2817 --- PASS: TestParseSigningKey/wrong_length (0.00s)2818 --- PASS: TestParseSigningKey/no_colon (0.00s)2819 --- PASS: TestParseSigningKey/empty_name (0.00s)2820 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2821=== PAUSE TestSignErrors/invalid_narinfo2822=== RUN TestSignErrors/canceled2823=== PAUSE TestSignErrors/canceled2824=== CONT TestGenerateFingerprint/basic_with_references2825=== CONT TestGenerateFingerprint/invalid_nar_hash_length2826=== CONT TestGenerateFingerprint/invalid_store_path_prefix2827=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2828=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2829=== CONT TestGenerateFingerprint/no_references2830=== CONT TestGenerateFingerprint/invalid_reference_prefix2831--- PASS: TestGenerateFingerprint (0.00s)2832 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2833 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2834 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2835 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2836 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2837 --- PASS: TestGenerateFingerprint/no_references (0.00s)2838 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2839=== CONT TestSignErrors/nil_key2840=== CONT TestSignErrors/canceled2841=== CONT TestSignErrors/nil_narinfo2842=== CONT TestSignErrors/invalid_narinfo2843--- PASS: TestSignErrors (0.00s)2844 --- PASS: TestSignErrors/nil_key (0.00s)2845 --- PASS: TestSignErrors/canceled (0.00s)2846 --- PASS: TestSignErrors/nil_narinfo (0.00s)2847 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2848--- PASS: TestExternalSignerClose (0.40s)2849--- PASS: TestExternalSignerRestartsAfterCrash (0.61s)2850/private/var/tb/3/scratch/5f72cc1e653f715f/build/TestExternalSignerRestartsAfterCrash2866343067/001/sign program: line 7: /private/var/tb/3/scratch/5f72cc1e653f715f/build/TestExternalSignerRestartsAfterCrash2866343067/001/sign program.starts: No such file or directory2851--- PASS: TestExternalSignerProgramErrorKeepsProcess (1.55s)2852--- PASS: TestExternalSigner (2.50s)2853--- PASS: TestExternalSignerCancellation (2.69s)2854--- PASS: TestExternalSignerWrongPublicKey (3.05s)2855--- PASS: TestExternalSignerErrors (0.00s)2856 --- PASS: TestExternalSignerErrors/unrequested_key (0.77s)2857 --- PASS: TestExternalSignerErrors/missing_signatures (0.97s)2858 --- PASS: TestExternalSignerErrors/exit_on_request (1.16s)2859 --- PASS: TestExternalSignerErrors/null_signatures (1.34s)2860 --- PASS: TestExternalSignerErrors/null (1.74s)2861 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.92s)2862 --- PASS: TestExternalSignerErrors/wrong_signature_length (2.11s)2863 --- PASS: TestExternalSignerErrors/missing_signature_name (2.29s)2864 --- PASS: TestExternalSignerErrors/exit_at_startup (2.86s)2865 --- PASS: TestExternalSignerErrors/wrong_id (3.24s)2866 --- PASS: TestExternalSignerErrors/wrong_signature_name (3.42s)2867 --- PASS: TestExternalSignerErrors/program_error (3.61s)2868 --- PASS: TestExternalSignerErrors/invalid_JSON (3.80s)2869 --- PASS: TestExternalSignerErrors/too_few_signatures (3.99s)2870 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (4.17s)2871 --- PASS: TestExternalSignerErrors/wrong_shape (4.36s)2872PASS2873Running OpenBao signer tests...2874=== RUN TestSign2875=== PAUSE TestSign2876=== RUN TestSignErrors2877=== PAUSE TestSignErrors2878=== RUN TestServe2879=== PAUSE TestServe2880=== RUN TestServeRejectsGarbage2881=== PAUSE TestServeRejectsGarbage2882=== CONT TestSign2883=== CONT TestServeRejectsGarbage2884=== CONT TestServe2885=== CONT TestSignErrors2886=== RUN TestSignErrors/http_error2887=== PAUSE TestSignErrors/http_error2888--- PASS: TestServeRejectsGarbage (0.00s)2889=== RUN TestSignErrors/invalid_json2890=== PAUSE TestSignErrors/invalid_json2891=== RUN TestSignErrors/no_prefix2892=== PAUSE TestSignErrors/no_prefix2893=== RUN TestSignErrors/invalid_base642894=== PAUSE TestSignErrors/invalid_base642895=== CONT TestSignErrors/http_error2896=== CONT TestSignErrors/no_prefix2897=== CONT TestSignErrors/invalid_base642898--- PASS: TestServe (0.00s)2899=== CONT TestSignErrors/invalid_json2900--- PASS: TestSign (0.00s)2901--- PASS: TestSignErrors (0.00s)2902 --- PASS: TestSignErrors/invalid_json (0.00s)2903 --- PASS: TestSignErrors/no_prefix (0.00s)2904 --- PASS: TestSignErrors/http_error (0.00s)2905 --- PASS: TestSignErrors/invalid_base64 (0.00s)2906PASS