niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #439
· 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 (0.19s)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 TestStreamPushIsolatesFailures118=== CONT TestSetClientTLS119=== CONT TestScriptTokenEmptyCommand120--- PASS: TestScriptTokenEmptyCommand (0.00s)121=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess122=== CONT TestScriptTokenScriptFails123=== CONT TestScriptTokenBadJSON124=== CONT TestScriptTokenEmptyToken1252026/10/27 08:16:03 WARN Rate limiter enabled after throttle name=server-test rate=51262026/10/27 08:16:03 ERROR Upload failed error="bad path" count=3127=== CONT TestScriptTokenCachesUntilRefresh128=== CONT TestScriptTokenNoExpiryRerunsEveryCall129=== CONT TestFileTokenEmpty130=== CONT TestFileTokenMissing131=== CONT TestFileTokenReadsAndCaches132=== CONT TestStaticToken133--- PASS: TestStreamPushIsolatesFailures (0.00s)134=== CONT TestRateLimiterFeedback135=== CONT TestPathInfoCACompatibility136=== RUN TestPathInfoCACompatibility/null_ca_field137=== RUN TestRateLimiterFeedback/429_enables_limiter138=== PAUSE TestPathInfoCACompatibility/null_ca_field139=== RUN TestPathInfoCACompatibility/old_string_format_-_text140=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text141=== PAUSE TestRateLimiterFeedback/429_enables_limiter142=== RUN TestRateLimiterFeedback/503_enables_limiter143=== PAUSE TestRateLimiterFeedback/503_enables_limiter144--- PASS: TestStaticToken (0.00s)145=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive146=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive1472026/10/27 08:16:03 WARN Rate limiter enabled after throttle name=server-test rate=5148=== CONT TestSetClientTLSDoesNotMutateDefaultTransport1492026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:62650150=== CONT TestShellSplitErrors151=== CONT TestParsePathInfoJSON152=== RUN TestParsePathInfoJSON/Nix_format153=== CONT TestStreamPushBatchesUnderLoad154=== CONT TestStreamPushReportsEveryPath155=== CONT TestDoWithRetry_FinalResponseBodyReadable156=== CONT TestShellSplit157=== CONT TestDumpPathWriterError158=== CONT TestResolveStorePath159=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer160=== CONT TestSetClientTLSErrors161=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter162=== RUN TestPathInfoCACompatibility/new_structured_format_-_text163--- PASS: TestDoServerRequestAttachesToken (0.00s)164=== CONT TestParsePathInfoJSONMultiplePaths165=== PAUSE TestParsePathInfoJSON/Nix_format166=== RUN TestParsePathInfoJSON/Lix_format167=== PAUSE TestParsePathInfoJSON/Lix_format168=== RUN TestParsePathInfoJSON/empty_input169=== PAUSE TestParsePathInfoJSON/empty_input170=== RUN TestParsePathInfoJSON/whitespace_only171=== PAUSE TestParsePathInfoJSON/whitespace_only172=== RUN TestParsePathInfoJSON/invalid_JSON173=== PAUSE TestParsePathInfoJSON/invalid_JSON174--- PASS: TestShellSplit (0.00s)175=== CONT TestEncodeNixBase32176=== RUN TestEncodeNixBase32/test_string_hash177=== PAUSE TestEncodeNixBase32/test_string_hash178=== RUN TestEncodeNixBase32/empty_input179=== PAUSE TestEncodeNixBase32/empty_input180=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter181=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter182=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter183=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text184=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method185=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method186--- PASS: TestShellSplitErrors (0.00s)187--- PASS: TestFileTokenMissing (0.00s)188--- PASS: TestFileTokenEmpty (0.01s)189--- PASS: TestFileTokenReadsAndCaches (0.00s)190=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths191=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths192=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths193=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths194=== CONT TestUploadMultipart_PartsInParallel1952026/10/27 08:16:03 WARN Rate limiter backed off name=server-test rate=51962026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:626501972026/10/27 08:16:03 WARN Rate limiter enabled after throttle name=server-test rate=51982026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:62655199=== CONT TestEncodeNixBase32WithRealHash200=== CONT TestUploadMultipart_FailedPartBufferNotReused201=== CONT TestStreamPushStopsWhenCanceled202=== CONT TestClientSignaturesByStorePath203=== CONT TestSupersededNARStillUploadsListing204=== CONT TestDumpPathMatchesNix205--- PASS: TestStreamPushReportsEveryPath (0.00s)206--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)207--- PASS: TestResolveStorePath (0.00s)208--- PASS: TestEncodeNixBase32WithRealHash (0.00s)209--- PASS: TestScriptTokenScriptFails (0.01s)210--- PASS: TestStreamPushStopsWhenCanceled (0.00s)211=== CONT TestRetryTimeoutOutlastsMaxRetries212--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)213--- PASS: TestClientSignaturesByStorePath (0.00s)214=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun215=== CONT TestFilterOversizedClosures216=== RUN TestSetClientTLS/rejects_connection_without_client_cert217=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert218=== CONT TestPathInfoHashCompatibility219=== CONT TestGetStorePathHash220=== CONT TestConvertHashToNix32221=== CONT TestDumpPathSingleFile222=== CONT TestPartSizeForNAR223=== RUN TestSetClientTLSErrors/missing_cert_file224=== CONT TestUploadMultipart_SupersededByPeer2252026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:62662226--- PASS: TestScriptTokenEmptyToken (0.01s)227--- PASS: TestScriptTokenBadJSON (0.02s)228=== CONT TestCaseHackSuffix229=== RUN TestFilterOversizedClosures/no_limit_keeps_everything230=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything231=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped232=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped233=== RUN TestFilterOversizedClosures/all_closures_skipped234=== PAUSE TestFilterOversizedClosures/all_closures_skipped235=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA236=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA237=== RUN TestSetClientTLS/preserves_debug_logging_transport238=== PAUSE TestSetClientTLS/preserves_debug_logging_transport239=== CONT TestStreamPushReportsSignatures240=== CONT TestStreamPushGivesUpOnDeadServer2412026/10/27 08:16:03 ERROR Upload failed error="connection refused" count=202422026/10/27 08:16:03 ERROR Server seems unavailable, giving up on batch untried=17243=== PAUSE TestSetClientTLSErrors/missing_cert_file244=== RUN TestSetClientTLSErrors/missing_key_file245=== CONT TestRegisterUploadedObjectReusesConnections2462026/10/27 08:16:03 ERROR Upload failed error=boom count=1247=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica2482026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:62662249=== RUN TestUploadMultipart_SupersededByPeer/exists250=== PAUSE TestUploadMultipart_SupersededByPeer/exists251=== RUN TestUploadMultipart_SupersededByPeer/missing252=== PAUSE TestUploadMultipart_SupersededByPeer/missing253=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry254=== CONT TestStreamPushRequestLine255=== PAUSE TestSetClientTLSErrors/missing_key_file256=== RUN TestSetClientTLSErrors/missing_ca_file257=== PAUSE TestSetClientTLSErrors/missing_ca_file258=== RUN TestSetClientTLSErrors/invalid_ca_file259=== PAUSE TestSetClientTLSErrors/invalid_ca_file260--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)261--- PASS: TestStreamPushReportsSignatures (0.00s)262=== CONT TestStreamPushReportsSkippedPaths263--- PASS: TestStreamPushReportsSkippedPaths (0.00s)264=== CONT TestParsePathInfoJSON/Nix_format265=== CONT TestParsePathInfoJSON/invalid_JSON266=== CONT TestParsePathInfoJSON/whitespace_only267=== CONT TestParsePathInfoJSON/empty_input268=== CONT TestParsePathInfoJSON/Lix_format269--- PASS: TestParsePathInfoJSON (0.00s)270 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)271 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)272 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)273 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)274 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)275=== CONT TestEncodeNixBase32/test_string_hash276=== CONT TestRateLimiterFeedback/429_enables_limiter2772026/10/27 08:16:03 ERROR Upload failed error=boom count=12782026/10/27 08:16:03 WARN Rate limiter backed off name=server-test rate=5279=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)280=== RUN TestGetStorePathHash/valid_store_path281=== RUN TestConvertHashToNix32/SRI_format_to_Nix32282=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32283=== RUN TestConvertHashToNix32/already_Nix32_format284=== PAUSE TestConvertHashToNix32/already_Nix32_format285=== RUN TestPartSizeForNAR/zero_stays_at_minimum286=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum287=== RUN TestPartSizeForNAR/small_stays_at_minimum288=== RUN TestSupersededNARStillUploadsListing/small_NAR289=== PAUSE TestSupersededNARStillUploadsListing/small_NAR290=== RUN TestSupersededNARStillUploadsListing/dump_cut_short291=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)292=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon293=== PAUSE TestPartSizeForNAR/small_stays_at_minimum294=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum295--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)296=== CONT TestPathInfoCACompatibility/null_ca_field2972026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:62662298=== PAUSE TestGetStorePathHash/valid_store_path299=== RUN TestConvertHashToNix32/invalid_format300=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short301=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails302=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails303=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon304=== CONT TestPathInfoCACompatibility/new_structured_format_-_text305=== CONT TestEncodeNixBase32/empty_input306--- PASS: TestEncodeNixBase32 (0.00s)307 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)308 --- PASS: TestEncodeNixBase32/empty_input (0.00s)309=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI310=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI311=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512312=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512313=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter314=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths315=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter316=== RUN TestGetStorePathHash/basename_without_hyphen_should_error317=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error318=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error319=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error320=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error321=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error322=== CONT TestRateLimiterFeedback/503_enables_limiter323=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method324=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive325=== CONT TestPathInfoCACompatibility/old_string_format_-_text326--- PASS: TestPathInfoCACompatibility (0.00s)327 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)328 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)329 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)330 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)331 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)332=== PAUSE TestConvertHashToNix32/invalid_format333=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths334--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)335 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)336 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)337=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum338=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts339=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts340=== RUN TestPartSizeForNAR/1_TiB341=== PAUSE TestPartSizeForNAR/1_TiB342=== RUN TestPartSizeForNAR/5_TiB_S3_max_object343=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object344=== RUN TestPartSizeForNAR/capped_at_5_GiB345=== PAUSE TestPartSizeForNAR/capped_at_5_GiB346=== CONT TestFilterOversizedClosures/no_limit_keeps_everything347=== CONT TestSetClientTLS/rejects_connection_without_client_cert348=== CONT TestFilterOversizedClosures/all_closures_skipped3492026/10/27 08:16:03 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=50350=== CONT TestSetClientTLS/preserves_debug_logging_transport351=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3522026/10/27 08:16:03 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=2000353--- PASS: TestFilterOversizedClosures (0.00s)354 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)355 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)356 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)357=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3582026/10/27 08:16:03 WARN Rate limiter enabled after throttle name=s3-test rate=53592026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:626713602026/10/27 08:16:03 INFO Garbage collection started3612026/10/27 08:16:03 INFO Garbage collection started3622026/10/27 08:16:03 WARN Rate limiter enabled after throttle name=server-test rate=53632026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:62676364--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.01s)365=== CONT TestUploadMultipart_SupersededByPeer/exists366=== CONT TestSetClientTLSErrors/missing_cert_file367=== CONT TestSetClientTLSErrors/missing_ca_file3682026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:62662369=== CONT TestSetClientTLSErrors/invalid_ca_file370=== CONT TestSetClientTLSErrors/missing_key_file3712026/10/27 08:16:03 WARN Rate limiter backed off name=server-test rate=5372=== CONT TestUploadMultipart_SupersededByPeer/missing373=== CONT TestSupersededNARStillUploadsListing/small_NAR3742026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:62662375=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3762026/10/27 08:16:03 WARN Rate limiter enabled after throttle name=server-test rate=53772026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:627423782026/10/27 08:16:03 INFO Uploading abc-hello (1.0GB)3792026/10/27 08:16:03 WARN Rate limiter backed off name=server-test rate=53802026/10/27 08:16:03 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=03812026/10/27 08:16:03 WARN Rate limiter enabled after throttle name=s3-test rate=53822026/10/27 08:16:03 INFO Uploading abc-hello (1.0GB)383=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3842026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:62662385=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error386=== CONT TestGetStorePathHash/basename_without_hyphen_should_error387=== CONT TestConvertHashToNix32/SRI_format_to_Nix32388=== CONT TestPartSizeForNAR/zero_stays_at_minimum389=== CONT TestConvertHashToNix32/invalid_format390=== CONT TestConvertHashToNix32/already_Nix32_format391=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts392=== CONT TestPartSizeForNAR/capped_at_5_GiB393=== CONT TestPartSizeForNAR/5_TiB_S3_max_object394=== CONT TestPartSizeForNAR/1_TiB395=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum396=== CONT TestPartSizeForNAR/small_stays_at_minimum3972026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:626623982026/10/27 08:16:03 WARN Garbage collection finished on another replica. Its statistics are not available here399--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)4002026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:62662401=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)402=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512403=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI404=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon405=== CONT TestGetStorePathHash/valid_store_path406=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error407--- PASS: TestStreamPushRequestLine (0.02s)408--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)409 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)410 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.00s)411--- PASS: TestRateLimiterFeedback (0.00s)412 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.01s)413 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)414 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)415 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.02s)416--- PASS: TestConvertHashToNix32 (0.00s)417 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)418 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)419 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)420--- PASS: TestPartSizeForNAR (0.00s)421 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)422 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)423 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)424 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)425 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)426 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)427 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)428--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)429--- PASS: TestSetClientTLSErrors (0.01s)430 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.01s)431 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)432 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)433 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.01s)434--- PASS: TestPathInfoHashCompatibility (0.00s)435 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)436 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)437 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)438 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)439--- PASS: TestGetStorePathHash (0.00s)440 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)441 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)442 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)443 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)4442026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:626624452026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:62662446--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)4472026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:626624482026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:626624492026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:626624502026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:62662451--- PASS: TestRegisterUploadedObjectReusesConnections (0.04s)4522026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:626624532026/10/27 08:16:03 http: TLS handshake error from 127.0.0.1:62698: read tcp 127.0.0.1:62658->127.0.0.1:62698: use of closed network connection4542026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:62662455--- PASS: TestSetClientTLS (0.02s)456 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)457 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)458 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.04s)4592026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:626624602026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:626624612026/10/27 08:16:03 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:62662462--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.05s)463--- PASS: TestDumpPathWriterError (0.06s)464--- PASS: TestScriptTokenCachesUntilRefresh (0.07s)4652026/10/27 08:16:03 INFO Uploading abc-hello (1.0GB)466--- PASS: TestCaseHackSuffix (0.06s)467--- PASS: TestDumpPathSingleFile (0.06s)4682026/10/27 08:16:03 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:62764/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:62764/part/24692026/10/27 08:16:03 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:62764/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:62764/part/34702026/10/27 08:16:03 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"471--- PASS: TestStreamPushBatchesUnderLoad (0.10s)472--- PASS: TestDumpPathMatchesNix (0.11s)473--- PASS: TestSupersededNARStillUploadsListing (0.01s)474 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)475 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.01s)476 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.55s)477--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.58s)478--- PASS: TestUploadMultipart_PartsInParallel (0.63s)479--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4802026/10/27 08:16:04 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:62659/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:62659/api/uploads/complete4812026/10/27 08:16:04 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:62659/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:62659/api/uploads/complete4822026/10/27 08:16:04 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4832026/10/27 08:16:04 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4842026/10/27 08:16:04 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:62659/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:62659/api/uploads/complete4852026/10/27 08:16:04 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"486--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.01s)487PASS488Running server tests...489The files belonging to this database system will be owned by user "_tribuchetbld4".490This user must also own the server process.491492The database cluster will be initialized with locale "C".493The default database encoding has accordingly been set to "SQL_ASCII".494The default text search configuration will be set to "english".495496Data page checksums are enabled.497498creating directory /private/var/tb/4/scratch/31ac9e0308c9e79b/build/postgres3901984444/data ... ok499creating subdirectories ... ok500selecting dynamic shared memory implementation ... posix501selecting default "max_connections" ... 100502selecting default "shared_buffers" ... 128MB503selecting default time zone ... UTC504creating configuration files ... ok505running bootstrap script ... ok506performing post-bootstrap initialization ... ok507syncing data to disk ... ok508509initdb: warning: enabling "trust" authentication for local connections510initdb: 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.511512Success. You can now start the database server using:513514 pg_ctl -D /private/var/tb/4/scratch/31ac9e0308c9e79b/build/postgres3901984444/data -l logfile start5155162026-10-27 08:16:07.458 UTC [68287] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5172026-10-27 08:16:07.458 UTC [68287] LOG: listening on Unix socket "/private/var/tb/4/scratch/31ac9e0308c9e79b/build/postgres3901984444/.s.PGSQL.5432"5182026-10-27 08:16:07.460 UTC [68294] LOG: database system was shut down at 2026-10-27 08:16:07 UTC5192026-10-27 08:16:07.461 UTC [68287] LOG: database system is ready to accept connections520/private/var/tb/4/scratch/31ac9e0308c9e79b/build/postgres3901984444:5432 - accepting connections521{"timestamp":"2026-10-27T08:16:09.715841Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"c6477172-5f94-4814-9ed5-22723bb1d40f","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(5)"}522=== RUN TestService_AuthMiddleware523=== PAUSE TestService_AuthMiddleware524=== RUN TestService_AuthMiddleware_MTLSProxyHeader525=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader526=== RUN TestService_AuthMiddleware_MTLSBoundSubjects527=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects528=== RUN TestService_ReadAuthMiddleware529=== PAUSE TestService_ReadAuthMiddleware530=== RUN TestService_AuthMiddleware_OIDC531=== PAUSE TestService_AuthMiddleware_OIDC532=== RUN TestService_RequireScope_OIDC533=== PAUSE TestService_RequireScope_OIDC534=== RUN TestService_ReadScope_PublicByDefault535=== PAUSE TestService_ReadScope_PublicByDefault536=== RUN TestCacheConfigHandler537=== PAUSE TestCacheConfigHandler538=== RUN TestCacheStatsHandler539=== PAUSE TestCacheStatsHandler540=== RUN TestClientCADerivations541=== PAUSE TestClientCADerivations542=== RUN TestClientErrorHandling543=== PAUSE TestClientErrorHandling544=== RUN TestClientIntegration545=== PAUSE TestClientIntegration546=== RUN TestClientMultipleUploads547=== PAUSE TestClientMultipleUploads548=== RUN TestClientWithDependencies549=== PAUSE TestClientWithDependencies550=== RUN TestClientSharedPathCommittedMidPush551=== PAUSE TestClientSharedPathCommittedMidPush552=== RUN TestPinProtectsFromGC553=== PAUSE TestPinProtectsFromGC554=== RUN TestClientPushesUseOnePush555=== PAUSE TestClientPushesUseOnePush556=== RUN TestClientFallsBackToClosures557=== PAUSE TestClientFallsBackToClosures558=== RUN TestDeleteClosuresRacingPins559=== PAUSE TestDeleteClosuresRacingPins560=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock561=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock562=== RUN TestResolveDBConnectionString563=== PAUSE TestResolveDBConnectionString564=== RUN TestConnectWaitsForAPeerMigration565=== PAUSE TestConnectWaitsForAPeerMigration566=== RUN TestLeadElectsOneAndHandsOver567=== PAUSE TestLeadElectsOneAndHandsOver568=== RUN TestLeadIncumbentWinsAfterRestart5692026/10/27 08:16:10 INFO lead: acquired remote=192.0.2.1:12345702026/10/27 08:16:10 INFO lead: released remote=192.0.2.1:12345712026/10/27 08:16:10 INFO lead: acquired remote=192.0.2.1:12345722026/10/27 08:16:11 INFO lead: released remote=192.0.2.1:1234573--- PASS: TestLeadIncumbentWinsAfterRestart (2.14s)574=== RUN TestLeadIncumbentAnnouncesAtOnce575=== PAUSE TestLeadIncumbentAnnouncesAtOnce576=== RUN TestLeadEndsOnShutdown577=== PAUSE TestLeadEndsOnShutdown578=== RUN TestLeadEndsWhenItsConnectionHangs5792026/10/27 08:16:12 INFO lead: acquired remote=192.0.2.1:12345802026-10-27 08:16:13.315 UTC [68338] FATAL: terminating connection due to administrator command5812026/10/27 08:16:13 INFO lead: acquired remote=192.0.2.1:12345822026/10/27 08:16:14 WARN lead: lock connection lost error="timeout: context deadline exceeded"5832026/10/27 08:16:14 INFO lead: released remote=192.0.2.1:12345842026/10/27 08:16:14 INFO lead: released remote=192.0.2.1:1234585--- PASS: TestLeadEndsWhenItsConnectionHangs (2.76s)586=== RUN TestGCAdvisoryLockBlocksConcurrentRun587=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun588=== RUN TestGCBugBareHashReferences589=== PAUSE TestGCBugBareHashReferences590=== RUN TestGCMetrics591=== PAUSE TestGCMetrics592=== RUN TestPushDedupSurvivesConcurrentGC593=== PAUSE TestPushDedupSurvivesConcurrentGC594=== RUN TestDeduplicatedObjectsRecordedAsPending595=== PAUSE TestDeduplicatedObjectsRecordedAsPending596=== RUN TestGCSweepSkipsPendingObjects597=== PAUSE TestGCSweepSkipsPendingObjects598=== RUN TestTombstonedObjectOfferedWithoutWaiting599=== PAUSE TestTombstonedObjectOfferedWithoutWaiting600=== RUN TestGCSweepDeliversEachKeyOnce601=== PAUSE TestGCSweepDeliversEachKeyOnce602=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection603=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection604=== RUN TestForceGCDuringPushOffersSweptObject605=== PAUSE TestForceGCDuringPushOffersSweptObject606=== RUN TestFailedS3DeleteKeepsTombstone607=== PAUSE TestFailedS3DeleteKeepsTombstone608=== RUN TestSweepSkipsRowsLockedByPush609=== PAUSE TestSweepSkipsRowsLockedByPush610=== RUN TestRegisterCompletedObjectNeedsPendingRow611=== PAUSE TestRegisterCompletedObjectNeedsPendingRow612=== RUN TestGetExistingObjectsLocksRows613=== PAUSE TestGetExistingObjectsLocksRows614=== RUN TestSweepRechecksPendingAfterLocking615=== PAUSE TestSweepRechecksPendingAfterLocking616=== RUN TestPushWaitsForSweepHoldingRow617=== PAUSE TestPushWaitsForSweepHoldingRow618=== RUN TestCommitRacingPendingCleanupKeepsObjects619=== PAUSE TestCommitRacingPendingCleanupKeepsObjects620=== RUN TestGCEndsOnShutdown621=== PAUSE TestGCEndsOnShutdown622=== RUN TestGCTaskStore_StartNew623=== PAUSE TestGCTaskStore_StartNew624=== RUN TestGCTaskStore_DeduplicateSameParams625=== PAUSE TestGCTaskStore_DeduplicateSameParams626=== RUN TestGCTaskStore_ConflictDifferentParams627=== PAUSE TestGCTaskStore_ConflictDifferentParams628=== RUN TestGCTaskStore_GetEmpty629=== PAUSE TestGCTaskStore_GetEmpty630=== RUN TestGCTaskStore_GetReturnsLatest631=== PAUSE TestGCTaskStore_GetReturnsLatest632=== RUN TestGCTaskStore_CompletedAllowsNewTask633=== PAUSE TestGCTaskStore_CompletedAllowsNewTask634=== RUN TestGCTaskStore_PhaseUpdates635=== PAUSE TestGCTaskStore_PhaseUpdates636=== RUN TestGCTaskStore_Fail637=== PAUSE TestGCTaskStore_Fail638=== RUN TestGracefulShutdownDrainsInflight639=== PAUSE TestGracefulShutdownDrainsInflight640=== RUN TestService_healthCheckHandler641=== PAUSE TestService_healthCheckHandler642=== RUN TestService_readinessHandler643=== PAUSE TestService_readinessHandler644=== RUN TestGenerateLandingPage645=== PAUSE TestGenerateLandingPage646=== RUN TestCacheConfigHandlerMaxNarSize647=== PAUSE TestCacheConfigHandlerMaxNarSize648=== RUN TestCreatePendingClosureRejectsOversizedNAR649=== PAUSE TestCreatePendingClosureRejectsOversizedNAR650=== RUN TestNARDeduplicationMetadataUploadBug651=== PAUSE TestNARDeduplicationMetadataUploadBug652=== RUN TestMetricsInventory653=== PAUSE TestMetricsInventory654=== RUN TestMetricsCommit655=== PAUSE TestMetricsCommit656=== RUN TestService_NativeMTLS657=== PAUSE TestService_NativeMTLS658=== RUN TestServerTLSConfig659=== PAUSE TestServerTLSConfig660=== RUN TestMultipartCleanup661=== PAUSE TestMultipartCleanup662=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded663=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded664=== RUN TestPendingCleanupUsesOneCutoff665=== PAUSE TestPendingCleanupUsesOneCutoff666=== RUN TestObjectStatsTrigger667=== PAUSE TestObjectStatsTrigger668=== RUN TestObjectStatsUpdatedOncePerCommit669=== PAUSE TestObjectStatsUpdatedOncePerCommit670=== RUN TestOrphanedObjectsGC671=== PAUSE TestOrphanedObjectsGC672=== RUN TestOrphanedObjectsGCStressTest673=== PAUSE TestOrphanedObjectsGCStressTest674=== RUN TestCreatePin_ReservedPins675=== PAUSE TestCreatePin_ReservedPins676=== RUN TestPresentReportsOnlyClosureRoots677=== PAUSE TestPresentReportsOnlyClosureRoots678=== RUN TestPresentRefreshesOnlyStaleClosures679=== PAUSE TestPresentRefreshesOnlyStaleClosures680=== RUN TestPresentNotReportedWhileGCDeletesClosure681=== PAUSE TestPresentNotReportedWhileGCDeletesClosure682=== RUN TestParseSingleRange683=== PAUSE TestParseSingleRange684=== RUN TestProxyHeadersOnlyTrustedOnSocket6852026/10/27 08:16:14 INFO Starting HTTP server address=proxy.sock6862026/10/27 08:16:14 INFO Starting HTTP server address=127.0.0.1:628306872026/10/27 08:16:14 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6882026/10/27 08:16:14 INFO Shutdown signal received, draining in-flight requests timeout=10s689--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)690=== RUN TestIsValidCachePath691=== PAUSE TestIsValidCachePath692=== RUN TestReadProxyNarinfo693=== PAUSE TestReadProxyNarinfo694=== RUN TestReadProxyNarinfoAlreadyDecompressed695=== PAUSE TestReadProxyNarinfoAlreadyDecompressed696=== RUN TestReadProxyContentNegotiation697=== PAUSE TestReadProxyContentNegotiation698=== RUN TestReadProxyNarStreaming699=== PAUSE TestReadProxyNarStreaming700=== RUN TestReadProxy404701=== PAUSE TestReadProxy404702=== RUN TestReadProxyInvalidPath703=== PAUSE TestReadProxyInvalidPath704=== RUN TestReadProxyHead705=== PAUSE TestReadProxyHead706=== RUN TestReadProxyOutlastsServerWriteTimeout707=== PAUSE TestReadProxyOutlastsServerWriteTimeout708=== RUN TestReadProxyConditionalGet709=== PAUSE TestReadProxyConditionalGet710=== RUN TestReadProxyRootRedirectsToIndexHTML711=== PAUSE TestReadProxyRootRedirectsToIndexHTML712=== RUN TestReadProxyDisabled713=== PAUSE TestReadProxyDisabled714=== RUN TestReadRedirectNar715=== PAUSE TestReadRedirectNar716=== RUN TestReadRedirectKeepsNarinfoProxied717=== PAUSE TestReadRedirectKeepsNarinfoProxied718=== RUN TestReadProxyRangeRequest719=== PAUSE TestReadProxyRangeRequest720=== RUN TestReadRedirectUsesPublicS3URL721=== PAUSE TestReadRedirectUsesPublicS3URL722=== RUN TestPush_OverlappingRootsStoreOneRowPerKey723=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey724=== RUN TestPush_CompleteCommitsEveryRoot725=== PAUSE TestPush_CompleteCommitsEveryRoot726=== RUN TestPush_RepeatedRootCommitsOnce727=== PAUSE TestPush_RepeatedRootCommitsOnce728=== RUN TestPush_CompleteWaitsForCleanupOfThePush729=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush730=== RUN TestPush_RootsAreLockedInByteOrder731=== PAUSE TestPush_RootsAreLockedInByteOrder732=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit733=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit734=== RUN TestPush_RejectsBadRequests735=== PAUSE TestPush_RejectsBadRequests736=== RUN TestPush_SignsNarinfosOfItsPendingObjects737=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects738=== RUN TestRedundantMultipartUpload739=== PAUSE TestRedundantMultipartUpload740=== RUN TestCompleteMultipartUpload_ErrorButObjectExists741=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists742=== RUN TestCompletedNarNotReofferedAcrossClosures743=== PAUSE TestCompletedNarNotReofferedAcrossClosures744=== RUN TestPresignedUploadRegisteredBeforeCommit745=== PAUSE TestPresignedUploadRegisteredBeforeCommit746=== RUN TestService_Rustfstest747=== PAUSE TestService_Rustfstest748=== RUN TestParseSize749=== PAUSE TestParseSize750=== RUN TestSkippedUploadsHandler751=== PAUSE TestSkippedUploadsHandler752=== RUN TestSystemdListenerNotActivated753--- PASS: TestSystemdListenerNotActivated (0.00s)754=== RUN TestWatchdogBeatsWhenHealthy755--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)756=== RUN TestWatchdogSkipsWhenUnhealthy7572026/10/27 08:16:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7582026/10/27 08:16:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7592026/10/27 08:16:14 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7602026/10/27 08:16:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7612026/10/27 08:16:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7622026/10/27 08:16:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7632026/10/27 08:16:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7642026/10/27 08:16:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7652026/10/27 08:16:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7662026/10/27 08:16:15 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"767--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)768=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle769=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle770=== RUN TestProxyWriteTimeout771=== PAUSE TestProxyWriteTimeout772=== RUN TestPendingClosureWriteTimeout773=== PAUSE TestPendingClosureWriteTimeout774=== RUN TestIsValidUploadKey775=== PAUSE TestIsValidUploadKey776=== RUN TestUploadHandlersRejectInvalidKeys777=== PAUSE TestUploadHandlersRejectInvalidKeys778=== RUN TestUploadHandlersRejectOversizedBody779=== PAUSE TestUploadHandlersRejectOversizedBody780=== RUN TestService_cleanupPendingClosuresHandler781=== PAUSE TestService_cleanupPendingClosuresHandler782=== RUN TestService_createPendingClosureHandler783=== PAUSE TestService_createPendingClosureHandler784=== RUN TestService_verifyS3Integrity785=== PAUSE TestService_verifyS3Integrity786=== RUN TestCompleteMultipartUnregistered787=== PAUSE TestCompleteMultipartUnregistered788=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT789=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT790=== CONT TestPush_SignsNarinfosOfItsPendingObjects791=== CONT TestPush_RootsAreLockedInByteOrder792=== CONT TestParseSingleRange793=== RUN TestParseSingleRange/none794=== CONT TestReadProxyRootRedirectsToIndexHTML795=== CONT TestService_NativeMTLS796=== CONT TestReadRedirectUsesPublicS3URL797=== CONT TestIsValidCachePath798=== RUN TestIsValidCachePath/narinfo799=== CONT TestReadProxyConditionalGet800=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT801=== PAUSE TestIsValidCachePath/narinfo802=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars803=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars804=== RUN TestIsValidCachePath/nar_zst805=== CONT TestService_AuthMiddleware806=== PAUSE TestParseSingleRange/none807=== CONT TestPresentNotReportedWhileGCDeletesClosure808=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale809=== CONT TestPresentRefreshesOnlyStaleClosures810=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale811=== CONT TestPresentReportsOnlyClosureRoots812=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh813=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh814=== CONT TestPush_CompleteWaitsForCleanupOfThePush815=== CONT TestCreatePin_ReservedPins816=== CONT TestOrphanedObjectsGCStressTest817=== CONT TestOrphanedObjectsGC818=== CONT TestObjectStatsUpdatedOncePerCommit819=== CONT TestObjectStatsTrigger820=== CONT TestPendingCleanupUsesOneCutoff821=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded822=== CONT TestMultipartCleanup823=== CONT TestServerTLSConfig824=== RUN TestServerTLSConfig/no_client_CA825=== PAUSE TestServerTLSConfig/no_client_CA826=== PAUSE TestIsValidCachePath/nar_zst827=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit828=== RUN TestParseSingleRange/unknown_unit829=== PAUSE TestParseSingleRange/unknown_unit830=== RUN TestParseSingleRange/multi-range_ignored831=== PAUSE TestParseSingleRange/multi-range_ignored832=== CONT TestPush_RejectsBadRequests833=== RUN TestIsValidCachePath/nar_xz834=== PAUSE TestIsValidCachePath/nar_xz835=== RUN TestIsValidCachePath/nar_bz2836=== PAUSE TestIsValidCachePath/nar_bz2837=== RUN TestParseSingleRange/malformed_no_dash838=== PAUSE TestParseSingleRange/malformed_no_dash839=== RUN TestIsValidCachePath/nar_uncompressed840=== PAUSE TestIsValidCachePath/nar_uncompressed841=== RUN TestIsValidCachePath/ls842=== PAUSE TestIsValidCachePath/ls843=== RUN TestIsValidCachePath/log844=== PAUSE TestIsValidCachePath/log845=== RUN TestIsValidCachePath/realisation846=== PAUSE TestIsValidCachePath/realisation847=== RUN TestIsValidCachePath/nix-cache-info848=== PAUSE TestIsValidCachePath/nix-cache-info849=== RUN TestIsValidCachePath/index.html850=== PAUSE TestIsValidCachePath/index.html851=== RUN TestIsValidCachePath/traversal_parent852=== RUN TestServerTLSConfig/missing_CA_file853=== RUN TestParseSingleRange/malformed_both_empty854=== PAUSE TestIsValidCachePath/traversal_parent855=== PAUSE TestServerTLSConfig/missing_CA_file856=== PAUSE TestParseSingleRange/malformed_both_empty857=== RUN TestParseSingleRange/malformed_end_before_start858=== PAUSE TestParseSingleRange/malformed_end_before_start859=== RUN TestParseSingleRange/closed860=== PAUSE TestParseSingleRange/closed861=== RUN TestParseSingleRange/open-ended862=== PAUSE TestParseSingleRange/open-ended863=== RUN TestParseSingleRange/end_clamped_to_size864=== PAUSE TestParseSingleRange/end_clamped_to_size865=== RUN TestParseSingleRange/suffix866=== PAUSE TestParseSingleRange/suffix867=== RUN TestParseSingleRange/suffix_exceeds_size868=== PAUSE TestParseSingleRange/suffix_exceeds_size869=== RUN TestParseSingleRange/single_byte870=== PAUSE TestParseSingleRange/single_byte871=== RUN TestParseSingleRange/start_past_EOF872=== PAUSE TestParseSingleRange/start_past_EOF873=== RUN TestParseSingleRange/start_far_past_EOF874=== PAUSE TestParseSingleRange/start_far_past_EOF875=== CONT TestPush_RepeatedRootCommitsOnce876=== RUN TestIsValidCachePath/traversal_in_middle877=== PAUSE TestIsValidCachePath/traversal_in_middle878=== RUN TestIsValidCachePath/invalid_char_e879=== PAUSE TestIsValidCachePath/invalid_char_e880=== RUN TestIsValidCachePath/invalid_char_u881=== PAUSE TestIsValidCachePath/invalid_char_u882=== RUN TestIsValidCachePath/random_path883=== RUN TestServerTLSConfig/not_a_PEM_file884=== PAUSE TestIsValidCachePath/random_path885=== PAUSE TestServerTLSConfig/not_a_PEM_file886=== RUN TestIsValidCachePath/empty887=== CONT TestPush_CompleteCommitsEveryRoot888=== PAUSE TestIsValidCachePath/empty889=== RUN TestIsValidCachePath/leading_slash890=== PAUSE TestIsValidCachePath/leading_slash891=== RUN TestIsValidCachePath/wrong_extension892=== PAUSE TestIsValidCachePath/wrong_extension893=== RUN TestIsValidCachePath/short_hash894=== PAUSE TestIsValidCachePath/short_hash895=== CONT TestPush_OverlappingRootsStoreOneRowPerKey8962026/10/27 08:16:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:62832/oidc8972026/10/27 08:16:16 INFO Received push request method=POST path=/api/pushes898--- PASS: TestObjectStatsUpdatedOncePerCommit (1.13s)899=== CONT TestReadProxy4049002026/10/27 08:16:16 INFO Received complete push request method=POST path=/api/pushes/1/complete9012026/10/27 08:16:16 INFO Received push request method=POST path=/api/pushes9022026/10/27 08:16:16 INFO Completed push id=1 objects=6 duration=79.456667ms903--- PASS: TestPush_CompleteCommitsEveryRoot (1.28s)904=== CONT TestReadProxyOutlastsServerWriteTimeout9052026/10/27 08:16:16 INFO Received complete push request method=POST path=/api/pushes/1/complete9062026/10/27 08:16:16 INFO Completed push id=1 objects=4 duration=50.383667ms907--- PASS: TestPush_RepeatedRootCommitsOnce (1.47s)908=== CONT TestReadProxyHead9092026/10/27 08:16:16 WARN mTLS auth: subject not in bound subjects subject="CN=reader"9102026/10/27 08:16:16 WARN mTLS auth: subject not in bound subjects subject="CN=reader"911--- PASS: TestService_NativeMTLS (1.57s)912=== CONT TestReadProxyInvalidPath9132026/10/27 08:16:16 INFO Received uploads request method=POST path=/api/pending_closures9142026/10/27 08:16:17 INFO Received cleanup request method=DELETE path=/api/pending_closures9152026/10/27 08:16:17 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket8/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""9162026/10/27 08:16:17 INFO Aborted multipart uploads count=0 kept=19172026/10/27 08:16:17 INFO Received cleanup request method=DELETE path=/api/pending_closures9182026/10/27 08:16:17 INFO Aborted multipart uploads count=1 kept=0919--- PASS: TestMultipartCleanup (2.10s)920=== CONT TestReadRedirectKeepsNarinfoProxied9212026/10/27 08:16:17 INFO Received uploads request method=POST path=/api/pending_closures922--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (2.18s)923=== CONT TestReadProxyRangeRequest924--- PASS: TestReadRedirectUsesPublicS3URL (2.37s)925=== CONT TestGCSweepSkipsPendingObjects926--- PASS: TestReadProxyConditionalGet (2.53s)927=== CONT TestMetricsCommit9282026/10/27 08:16:18 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"929--- PASS: TestService_AuthMiddleware (2.93s)930=== CONT TestMetricsInventory9312026/10/27 08:16:18 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9322026/10/27 08:16:18 WARN Refused reserved pin name=worker-x86_64-linux9332026/10/27 08:16:18 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux9342026/10/27 08:16:18 INFO Received create pin request method=POST path=/api/pins/my-app9352026/10/27 08:16:18 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux936--- PASS: TestCreatePin_ReservedPins (3.45s)937=== CONT TestNARDeduplicationMetadataUploadBug938--- PASS: TestPresentReportsOnlyClosureRoots (3.79s)939=== CONT TestCreatePendingClosureRejectsOversizedNAR9402026/10/27 08:16:18 INFO Received uploads request method=POST path=/api/pending_closures941--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)942=== CONT TestCacheConfigHandlerMaxNarSize943--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)944=== CONT TestGenerateLandingPage945--- PASS: TestGenerateLandingPage (0.00s)946=== CONT TestService_readinessHandler9472026/10/27 08:16:19 INFO Received push request method=POST path=/api/pushes9482026/10/27 08:16:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9492026/10/27 08:16:19 INFO Signed narinfos id=1 count=19502026/10/27 08:16:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9512026/10/27 08:16:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9522026/10/27 08:16:19 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"9532026/10/27 08:16:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9542026/10/27 08:16:19 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"9552026/10/27 08:16:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9562026/10/27 08:16:19 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=19572026/10/27 08:16:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign9582026/10/27 08:16:19 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo959--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (4.16s)960=== CONT TestService_healthCheckHandler961=== NAME TestOrphanedObjectsGC962 orphaned_objects_gc_test.go:287: GC Test Summary:963 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A964 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B965 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)966 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)967 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects968--- PASS: TestOrphanedObjectsGC (4.52s)969=== CONT TestGracefulShutdownDrainsInflight9702026/10/27 08:16:19 INFO Starting HTTP server address=127.0.0.1:628769712026/10/27 08:16:19 INFO Shutdown signal received, draining in-flight requests timeout=10s9722026/10/27 08:16:19 INFO Received push request method=POST path=/api/pushes973--- PASS: TestGracefulShutdownDrainsInflight (0.07s)974=== CONT TestGCTaskStore_Fail975--- PASS: TestGCTaskStore_Fail (0.00s)976=== CONT TestGCTaskStore_PhaseUpdates977--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)978=== CONT TestGCTaskStore_CompletedAllowsNewTask979--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)980=== CONT TestGCTaskStore_GetReturnsLatest981--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)982=== CONT TestGCTaskStore_GetEmpty983--- PASS: TestGCTaskStore_GetEmpty (0.00s)984=== CONT TestGCTaskStore_ConflictDifferentParams985--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)986=== CONT TestCompleteMultipartUnregistered9872026/10/27 08:16:19 INFO Received complete push request method=POST path=/api/pushes/1/complete9882026/10/27 08:16:19 INFO Completed push id=1 objects=4 duration=26.436834ms9892026/10/27 08:16:19 INFO Received push request method=POST path=/api/pushes9902026/10/27 08:16:19 INFO Received push request method=POST path=/api/pushes9912026/10/27 08:16:19 INFO Aborted multipart uploads count=0 kept=09922026/10/27 08:16:19 WARN Force mode enabled - objects will be deleted immediately without grace period9932026/10/27 08:16:19 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=09942026/10/27 08:16:19 INFO Vacuumed table table=pending_closures9952026/10/27 08:16:20 INFO Vacuumed table table=pending_objects9962026/10/27 08:16:20 INFO Vacuumed table table=multipart_uploads9972026/10/27 08:16:20 INFO Vacuumed table table=closures9982026/10/27 08:16:20 INFO Vacuumed table table=objects9992026/10/27 08:16:20 INFO Received complete push request method=POST path=/api/pushes/2/complete10002026/10/27 08:16:20 INFO Completed push id=2 objects=4 duration=6.884458ms1001--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (4.95s)1002=== CONT TestService_verifyS3Integrity1003--- PASS: TestReadProxyRootRedirectsToIndexHTML (5.06s)1004=== CONT TestService_createPendingClosureHandler10052026-10-27 08:16:20.289 UTC [68456] ERROR: Push does not exist: id=110062026-10-27 08:16:20.289 UTC [68456] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE10072026-10-27 08:16:20.289 UTC [68456] STATEMENT: SELECT commit_push($1)1008--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (5.17s)1009=== CONT TestService_cleanupPendingClosuresHandler1010--- PASS: TestPresentRefreshesOnlyStaleClosures (5.29s)1011=== CONT TestGCTaskStore_DeduplicateSameParams1012--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1013=== CONT TestUploadHandlersRejectOversizedBody1014=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure1015=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure1016=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart1017=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart1018=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts1019=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1020=== CONT TestGCTaskStore_StartNew1021--- PASS: TestGCTaskStore_StartNew (0.00s)1022=== CONT TestUploadHandlersRejectInvalidKeys1023=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1024=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info1025=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1026=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal1027=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1028=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key1029=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1030=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key1031=== CONT TestIsValidUploadKey1032=== RUN TestIsValidUploadKey/narinfo1033=== PAUSE TestIsValidUploadKey/narinfo1034=== RUN TestIsValidUploadKey/nar_zst1035=== PAUSE TestIsValidUploadKey/nar_zst1036=== RUN TestIsValidUploadKey/nar_xz1037=== PAUSE TestIsValidUploadKey/nar_xz1038=== RUN TestIsValidUploadKey/nar_plain1039=== PAUSE TestIsValidUploadKey/nar_plain1040=== RUN TestIsValidUploadKey/listing1041=== PAUSE TestIsValidUploadKey/listing1042=== RUN TestIsValidUploadKey/build_log1043=== PAUSE TestIsValidUploadKey/build_log1044=== RUN TestIsValidUploadKey/build_log_home-manager_file1045=== PAUSE TestIsValidUploadKey/build_log_home-manager_file1046=== RUN TestIsValidUploadKey/build_log_plus_in_name1047=== PAUSE TestIsValidUploadKey/build_log_plus_in_name1048=== RUN TestIsValidUploadKey/build_log_question_mark1049=== PAUSE TestIsValidUploadKey/build_log_question_mark1050=== RUN TestIsValidUploadKey/build_log_equals1051=== PAUSE TestIsValidUploadKey/build_log_equals1052=== RUN TestIsValidUploadKey/realisation1053=== PAUSE TestIsValidUploadKey/realisation1054=== RUN TestIsValidUploadKey/realisation_plus_in_output1055=== PAUSE TestIsValidUploadKey/realisation_plus_in_output1056=== RUN TestIsValidUploadKey/nix-cache-info1057=== PAUSE TestIsValidUploadKey/nix-cache-info1058=== RUN TestIsValidUploadKey/index.html1059=== PAUSE TestIsValidUploadKey/index.html1060=== RUN TestIsValidUploadKey/narinfo_key,_nar_type1061=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type1062=== RUN TestIsValidUploadKey/nar_key,_narinfo_type1063=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type1064=== RUN TestIsValidUploadKey/listing_key,_narinfo_type1065=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type1066=== RUN TestIsValidUploadKey/traversal1067=== PAUSE TestIsValidUploadKey/traversal1068=== RUN TestIsValidUploadKey/traversal_nar1069=== PAUSE TestIsValidUploadKey/traversal_nar1070=== RUN TestIsValidUploadKey/absolute1071=== PAUSE TestIsValidUploadKey/absolute1072=== RUN TestIsValidUploadKey/empty_key1073=== PAUSE TestIsValidUploadKey/empty_key1074=== RUN TestIsValidUploadKey/unknown_type1075=== PAUSE TestIsValidUploadKey/unknown_type1076=== CONT TestPendingClosureWriteTimeout1077=== RUN TestPendingClosureWriteTimeout/empty1078=== PAUSE TestPendingClosureWriteTimeout/empty1079=== RUN TestPendingClosureWriteTimeout/400_objects1080=== PAUSE TestPendingClosureWriteTimeout/400_objects1081=== RUN TestPendingClosureWriteTimeout/670k_objects1082=== PAUSE TestPendingClosureWriteTimeout/670k_objects1083=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1084=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1085=== CONT TestGCEndsOnShutdown1086=== RUN TestGCEndsOnShutdown/before_the_run1087=== PAUSE TestGCEndsOnShutdown/before_the_run1088=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1089=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1090=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1091=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1092=== CONT TestProxyWriteTimeout1093=== RUN TestProxyWriteTimeout/narinfo1094=== PAUSE TestProxyWriteTimeout/narinfo1095=== RUN TestProxyWriteTimeout/1_GiB_nar1096=== PAUSE TestProxyWriteTimeout/1_GiB_nar1097=== RUN TestProxyWriteTimeout/10_GiB_nar1098=== PAUSE TestProxyWriteTimeout/10_GiB_nar1099=== RUN TestProxyWriteTimeout/unknown_size1100=== PAUSE TestProxyWriteTimeout/unknown_size1101=== CONT TestCommitRacingPendingCleanupKeepsObjects11022026/10/27 08:16:20 INFO Received push request method=POST path=/api/pushes11032026-10-27 08:16:20.826 UTC [68467] ERROR: could not obtain lock on row in relation "closures"11042026-10-27 08:16:20.826 UTC [68467] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11052026-10-27 08:16:20.829 UTC [68467] ERROR: could not obtain lock on row in relation "closures"11062026-10-27 08:16:20.829 UTC [68467] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11072026-10-27 08:16:20.833 UTC [68467] ERROR: could not obtain lock on row in relation "closures"11082026-10-27 08:16:20.833 UTC [68467] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11092026-10-27 08:16:20.840 UTC [68467] ERROR: could not obtain lock on row in relation "closures"11102026-10-27 08:16:20.840 UTC [68467] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11112026-10-27 08:16:20.844 UTC [68467] ERROR: could not obtain lock on row in relation "closures"11122026-10-27 08:16:20.844 UTC [68467] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1113--- PASS: TestPush_RootsAreLockedInByteOrder (5.75s)1114=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1115=== RUN TestPush_RejectsBadRequests/bad_root1116=== PAUSE TestPush_RejectsBadRequests/bad_root1117=== RUN TestPush_RejectsBadRequests/root_not_in_objects1118=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1119=== RUN TestPush_RejectsBadRequests/no_roots1120=== PAUSE TestPush_RejectsBadRequests/no_roots1121=== RUN TestPush_RejectsBadRequests/no_objects1122=== PAUSE TestPush_RejectsBadRequests/no_objects1123=== CONT TestSkippedUploadsHandler11242026/10/27 08:16:20 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001125--- PASS: TestSkippedUploadsHandler (0.00s)1126=== CONT TestParseSize1127--- PASS: TestParseSize (0.00s)1128=== CONT TestService_Rustfstest11292026/10/27 08:16:21 INFO Received push request method=POST path=/api/pushes1130--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.21s)1131=== CONT TestPresignedUploadRegisteredBeforeCommit11322026/10/27 08:16:21 INFO Received uploads request method=POST path=/api/pending_closures11332026/10/27 08:16:21 INFO Received uploads request method=POST path=/api/pending_closures11342026/10/27 08:16:21 INFO Received cleanup request method=DELETE path=/api/pending_closures11352026/10/27 08:16:21 INFO Received uploads request method=POST path=/api/pending_closures1136--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (6.87s)1137=== CONT TestCompletedNarNotReofferedAcrossClosures1138--- PASS: TestObjectStatsTrigger (7.08s)1139=== CONT TestPushWaitsForSweepHoldingRow1140--- PASS: TestReadProxyHead (5.91s)1141=== CONT TestCompleteMultipartUpload_ErrorButObjectExists1142--- PASS: TestReadProxyInvalidPath (6.35s)1143=== CONT TestSweepRechecksPendingAfterLocking1144--- PASS: TestReadProxy404 (7.02s)1145=== CONT TestRedundantMultipartUpload1146--- PASS: TestReadRedirectKeepsNarinfoProxied (6.49s)1147=== CONT TestGetExistingObjectsLocksRows1148--- PASS: TestReadProxyRangeRequest (6.70s)1149=== CONT TestRegisterCompletedObjectNeedsPendingRow11502026/10/27 08:16:24 INFO Received uploads request method=POST path=/api/pending_closures11512026/10/27 08:16:24 INFO Aborted multipart uploads count=0 kept=011522026/10/27 08:16:24 WARN Force mode enabled - objects will be deleted immediately without grace period11532026/10/27 08:16:24 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=011542026/10/27 08:16:24 INFO Vacuumed table table=pending_closures11552026/10/27 08:16:24 INFO Vacuumed table table=pending_objects11562026/10/27 08:16:24 INFO Vacuumed table table=multipart_uploads11572026/10/27 08:16:24 INFO Vacuumed table table=closures11582026/10/27 08:16:24 INFO Vacuumed table table=objects1159--- PASS: TestGCSweepSkipsPendingObjects (6.96s)1160=== CONT TestReadProxyContentNegotiation11612026/10/27 08:16:24 INFO Received push request method=POST path=/api/pushes11622026/10/27 08:16:24 INFO Received complete push request method=POST path=/api/pushes/1/complete11632026/10/27 08:16:24 INFO Completed push id=1 objects=4 duration=46.530459ms11642026/10/27 08:16:24 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11652026/10/27 08:16:24 INFO Completed upload id=2 objects=2 duration=1.755625ms1166--- PASS: TestMetricsCommit (7.03s)1167=== CONT TestReadProxyNarStreaming1168--- PASS: TestMetricsInventory (6.80s)1169=== CONT TestSweepSkipsRowsLockedByPush1170=== NAME TestNARDeduplicationMetadataUploadBug1171 metadata_upload_test.go:48: First store path: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestNARDeduplicationMetadataUploadBug1286862721/001/store/rvnn21gj2wcxxwdighlf1x8ddc93vn64-file1.txt11722026/10/27 08:16:25 WARN readiness check failed error="closed pool"1173--- PASS: TestService_readinessHandler (6.39s)1174=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection11752026/10/27 08:16:25 INFO Received push request method=POST path=/api/pushes11762026/10/27 08:16:25 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11772026/10/27 08:16:25 INFO Uploading rvnn21gj2wcxxwdighlf1x8ddc93vn64-file1.txt (160B)11782026/10/27 08:16:25 WARN Failed to register uploaded object key=rvnn21gj2wcxxwdighlf1x8ddc93vn64.ls error="server returned 404: 404 page not found\n"11792026/10/27 08:16:25 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11802026/10/27 08:16:25 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11812026/10/27 08:16:25 INFO Signed narinfos id=1 count=111822026/10/27 08:16:25 INFO Uploading 1 narinfos1183--- PASS: TestService_healthCheckHandler (6.28s)1184=== CONT TestFailedS3DeleteKeepsTombstone11852026/10/27 08:16:25 INFO Received complete push request method=POST path=/api/pushes/1/complete11862026/10/27 08:16:25 WARN Failed to register uploaded object key=rvnn21gj2wcxxwdighlf1x8ddc93vn64.narinfo error="server returned 404: 404 page not found\n"11872026/10/27 08:16:25 INFO Completed push id=1 objects=3 duration=20.142583ms11882026/10/27 08:16:25 INFO Upload complete. (226ms)1189=== NAME TestNARDeduplicationMetadataUploadBug1190 metadata_upload_test.go:54: Retrieved narinfo from S3:1191 StorePath: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestNARDeduplicationMetadataUploadBug1286862721/001/store/rvnn21gj2wcxxwdighlf1x8ddc93vn64-file1.txt1192 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1193 Compression: zstd1194 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1195 NarSize: 1601196 References: 1197 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1198 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1199 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1200 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1201 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestNARDeduplicationMetadataUploadBug1286862721/001/store/df8jbkwhswz5igajvqs2fy8vda9r0ya0-file2.txt12022026/10/27 08:16:25 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12032026/10/27 08:16:25 INFO Received push request method=POST path=/api/pushes12042026/10/27 08:16:25 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)12052026/10/27 08:16:25 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1206--- PASS: TestCompleteMultipartUnregistered (6.07s)1207=== CONT TestForceGCDuringPushOffersSweptObject1208=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1209=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1210=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1211=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1212=== CONT TestReadRedirectNar12132026/10/27 08:16:25 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12142026/10/27 08:16:25 WARN Failed to register uploaded object key=df8jbkwhswz5igajvqs2fy8vda9r0ya0.ls error="server returned 404: 404 page not found\n"12152026/10/27 08:16:25 INFO Signed narinfos id=2 count=112162026/10/27 08:16:25 INFO Uploading 1 narinfos12172026/10/27 08:16:25 INFO Received complete push request method=POST path=/api/pushes/2/complete12182026/10/27 08:16:25 WARN Failed to register uploaded object key=df8jbkwhswz5igajvqs2fy8vda9r0ya0.narinfo error="server returned 404: 404 page not found\n"12192026/10/27 08:16:25 INFO Completed push id=2 objects=3 duration=701.292µs12202026/10/27 08:16:25 INFO Upload complete. (144ms)1221=== NAME TestNARDeduplicationMetadataUploadBug1222 metadata_upload_test.go:76: Retrieved narinfo from S3:1223 StorePath: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestNARDeduplicationMetadataUploadBug1286862721/001/store/df8jbkwhswz5igajvqs2fy8vda9r0ya0-file2.txt1224 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1225 Compression: zstd1226 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1227 NarSize: 1601228 References: 1229 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1230 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1231 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1232 {"version":1,"root":{"type":"regular","size":44}}1233--- PASS: TestNARDeduplicationMetadataUploadBug (7.36s)1234=== CONT TestGCSweepDeliversEachKeyOnce12352026/10/27 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures12362026/10/27 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures12372026/10/27 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures12382026/10/27 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures12392026/10/27 08:16:26 INFO Received cleanup request method=DELETE path=/api/pending_closures12402026/10/27 08:16:26 INFO Aborted multipart uploads count=0 kept=012412026/10/27 08:16:26 INFO Received uploads request method=POST path=/api/pending_closures12422026/10/27 08:16:26 INFO Received cleanup request method=DELETE path=/api/pending_closures12432026/10/27 08:16:26 INFO Aborted multipart uploads count=1 kept=012442026/10/27 08:16:26 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12452026-10-27 08:16:26.788 UTC [68483] ERROR: Closure does not exist: id=112462026-10-27 08:16:26.788 UTC [68483] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE12472026-10-27 08:16:26.788 UTC [68483] STATEMENT: -- name: CommitPendingClosure :one1248 SELECT commit_pending_closure($1::bigint)::bigint1249 1250--- PASS: TestService_cleanupPendingClosuresHandler (6.49s)1251=== CONT TestTombstonedObjectOfferedWithoutWaiting12522026/10/27 08:16:27 INFO Aborted multipart uploads count=0 kept=012532026/10/27 08:16:27 WARN Force mode enabled - objects will be deleted immediately without grace period12542026/10/27 08:16:27 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=012552026/10/27 08:16:27 INFO Vacuumed table table=pending_closures12562026/10/27 08:16:27 INFO Vacuumed table table=pending_objects12572026/10/27 08:16:27 INFO Vacuumed table table=multipart_uploads12582026/10/27 08:16:27 INFO Vacuumed table table=closures12592026/10/27 08:16:27 INFO Vacuumed table table=objects12602026/10/27 08:16:27 INFO Received uploads request method=POST path=/api/pending_closures1261--- PASS: TestCommitRacingPendingCleanupKeepsObjects (6.90s)1262=== CONT TestReadProxyDisabled1263--- PASS: TestReadProxyOutlastsServerWriteTimeout (11.28s)1264=== CONT TestPinProtectsFromGC12652026/10/27 08:16:27 INFO Aborted multipart uploads count=1 kept=01266--- PASS: TestService_Rustfstest (6.83s)12672026/10/27 08:16:27 INFO Received cleanup request method=DELETE path=/api/pending_closures1268=== CONT TestLeadElectsOneAndHandsOver12692026/10/27 08:16:27 INFO Aborted multipart uploads count=1 kept=01270--- PASS: TestPendingCleanupUsesOneCutoff (12.68s)1271=== CONT TestConnectWaitsForAPeerMigration12722026/10/27 08:16:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12732026/10/27 08:16:27 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12742026/10/27 08:16:28 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=ODgyODljOTktMDZhNy00NTZiLWE4ZjUtZjk0N2EwZTcyMTY0LjY5MTI0OTMxLWNlMDgtNGVjNC04YmE2LWY2ZWNkY2NkODkyYngxNzkzMDg4OTg2MDY0NDU0MDAw parts=1012752026/10/27 08:16:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12762026/10/27 08:16:28 INFO Completed upload id=1 objects=2 duration=24.7525ms12772026/10/27 08:16:28 INFO Received uploads request method=POST path=/api/pending_closures12782026/10/27 08:16:28 INFO Received uploads request method=POST path=/api/pending_closures12792026/10/27 08:16:28 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo12802026/10/27 08:16:28 WARN Found objects in DB but missing from S3, will re-upload count=11281--- PASS: TestService_verifyS3Integrity (8.02s)1282=== CONT TestResolveDBConnectionString1283=== RUN TestResolveDBConnectionString/flag_wins1284=== PAUSE TestResolveDBConnectionString/flag_wins1285=== RUN TestResolveDBConnectionString/file_when_flag_empty1286=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1287=== RUN TestResolveDBConnectionString/missing_file_is_an_error1288=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1289=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1290=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1291=== RUN TestResolveDBConnectionString/nothing_configured1292=== PAUSE TestResolveDBConnectionString/nothing_configured1293=== CONT TestCacheStatsHandler12942026/10/27 08:16:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12952026/10/27 08:16:28 INFO Received uploads request method=POST path=/api/pending_closures12962026/10/27 08:16:28 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=ODgyODljOTktMDZhNy00NTZiLWE4ZjUtZjk0N2EwZTcyMTY0LjNhZjM3MDQ0LWE4NGQtNDdkZi05N2E5LTVlYTM1M2MwYzJlYXgxNzkzMDg4OTg2MzUyNTkyMDAw parts=1012972026/10/27 08:16:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12982026/10/27 08:16:28 INFO Completed upload id=1 objects=2 duration=19.962042ms12992026/10/27 08:16:28 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000013002026/10/27 08:16:28 INFO Received uploads request method=POST path=/api/pending_closures13012026/10/27 08:16:28 INFO Starting cleanup of old closures method=DELETE path=/api/closures13022026/10/27 08:16:28 INFO Aborted multipart uploads count=0 kept=013032026/10/27 08:16:28 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=013042026/10/27 08:16:28 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst13052026/10/27 08:16:28 INFO Received uploads request method=POST path=/api/pending_closures1306--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.11s)13072026/10/27 08:16:28 INFO Vacuumed table table=pending_closures1308=== CONT TestClientSharedPathCommittedMidPush13092026/10/27 08:16:28 INFO Vacuumed table table=pending_objects13102026/10/27 08:16:28 INFO Vacuumed table table=multipart_uploads13112026/10/27 08:16:28 INFO Vacuumed table table=closures13122026/10/27 08:16:28 INFO Vacuumed table table=objects13132026/10/27 08:16:28 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001314--- PASS: TestService_createPendingClosureHandler (8.47s)1315=== CONT TestClientWithDependencies13162026/10/27 08:16:28 INFO Received uploads request method=POST path=/api/pending_closures13172026/10/27 08:16:29 INFO Received uploads request method=POST path=/api/pending_closures13182026/10/27 08:16:29 INFO Received uploads request method=POST path=/api/pending_closures1319--- PASS: TestPushWaitsForSweepHoldingRow (7.47s)1320=== CONT TestClientMultipleUploads13212026/10/27 08:16:29 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13222026/10/27 08:16:29 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ODgyODljOTktMDZhNy00NTZiLWE4ZjUtZjk0N2EwZTcyMTY0LjcxMjc5ZjczLWY2MTItNGFmZS1hYTRlLTJmOTg5MDZlNDcwYngxNzkzMDg4OTg5NTY4NDExMDAw13232026/10/27 08:16:30 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=ODgyODljOTktMDZhNy00NTZiLWE4ZjUtZjk0N2EwZTcyMTY0LjcxMjc5ZjczLWY2MTItNGFmZS1hYTRlLTJmOTg5MDZlNDcwYngxNzkzMDg4OTg5NTY4NDExMDAw parts=11324--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (7.50s)1325=== CONT TestClientIntegration13262026/10/27 08:16:30 INFO Aborted multipart uploads count=0 kept=013272026/10/27 08:16:30 WARN Force mode enabled - objects will be deleted immediately without grace period13282026/10/27 08:16:30 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=013292026/10/27 08:16:30 INFO Vacuumed table table=pending_closures13302026/10/27 08:16:30 INFO Vacuumed table table=pending_objects13312026/10/27 08:16:30 INFO Vacuumed table table=multipart_uploads13322026/10/27 08:16:30 INFO Vacuumed table table=closures13332026/10/27 08:16:30 INFO Vacuumed table table=objects1334--- PASS: TestSweepRechecksPendingAfterLocking (7.33s)13352026/10/27 08:16:30 INFO Received uploads request method=POST path=/api/pending_closures1336=== CONT TestClientErrorHandling1337=== RUN TestClientErrorHandling/InvalidStorePath1338=== PAUSE TestClientErrorHandling/InvalidStorePath1339=== RUN TestClientErrorHandling/InvalidAuthToken1340=== PAUSE TestClientErrorHandling/InvalidAuthToken1341=== RUN TestClientErrorHandling/ServerNotAvailable1342=== PAUSE TestClientErrorHandling/ServerNotAvailable1343=== CONT TestClientCADerivations1344=== NAME TestOrphanedObjectsGCStressTest1345 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains1346 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion13472026/10/27 08:16:30 INFO Received uploads request method=POST path=/api/pending_closures1348--- PASS: TestGetExistingObjectsLocksRows (7.26s)1349=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock13502026/10/27 08:16:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13512026/10/27 08:16:31 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=ODgyODljOTktMDZhNy00NTZiLWE4ZjUtZjk0N2EwZTcyMTY0LmRmYzBiMTFjLWYzODEtNDQ5NS05MmI2LThlNjczYWEwOGE0N3gxNzkzMDg4OTg4NzY5NzQyMDAw parts=1213522026/10/27 08:16:31 INFO Received uploads request method=POST path=/api/pending_closures1353--- PASS: TestCompletedNarNotReofferedAcrossClosures (9.36s)1354=== CONT TestDeleteClosuresRacingPins1355--- PASS: TestRegisterCompletedObjectNeedsPendingRow (7.41s)1356=== CONT TestClientFallsBackToClosures1357--- PASS: TestReadProxyContentNegotiation (7.64s)1358=== CONT TestClientPushesUseOnePush1359--- PASS: TestReadProxyNarStreaming (7.62s)1360=== CONT TestGCMetrics13612026/10/27 08:16:32 WARN Rate limiter enabled after throttle name=s3-test rate=513622026/10/27 08:16:32 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1363=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1364 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101365 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001366--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (11.74s)1367=== CONT TestReadProxyNarinfo13682026/10/27 08:16:32 INFO Aborted multipart uploads count=0 kept=013692026/10/27 08:16:32 WARN Force mode enabled - objects will be deleted immediately without grace period13702026/10/27 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=013712026/10/27 08:16:32 INFO Vacuumed table table=pending_closures13722026/10/27 08:16:32 INFO Vacuumed table table=pending_objects13732026/10/27 08:16:32 INFO Vacuumed table table=multipart_uploads13742026/10/27 08:16:32 INFO Vacuumed table table=closures13752026/10/27 08:16:32 INFO Vacuumed table table=objects13762026/10/27 08:16:32 INFO Aborted multipart uploads count=0 kept=013772026/10/27 08:16:32 WARN Force mode enabled - objects will be deleted immediately without grace period13782026/10/27 08:16:33 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13792026/10/27 08:16:33 INFO Received uploads request method=POST path=/api/pending_closures13802026/10/27 08:16:33 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=ODgyODljOTktMDZhNy00NTZiLWE4ZjUtZjk0N2EwZTcyMTY0LjViODA0MTgzLWEwMzYtNDhiNy04OWJjLWJjY2JmMjViZWY3N3gxNzkzMDg4OTkwNDQyNDYwMDAw parts=1213812026/10/27 08:16:33 INFO Received uploads request method=POST path=/api/pending_closures13822026/10/27 08:16:33 INFO Received uploads request method=POST path=/api/pending_closures13832026/10/27 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=1 objects-failed-to-delete=013842026/10/27 08:16:33 INFO Vacuumed table table=pending_closures13852026/10/27 08:16:33 INFO Vacuumed table table=pending_objects13862026/10/27 08:16:33 INFO Vacuumed table table=multipart_uploads13872026/10/27 08:16:33 INFO Vacuumed table table=closures1388--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (8.10s)1389=== CONT TestDeduplicatedObjectsRecordedAsPending13902026/10/27 08:16:33 INFO Vacuumed table table=objects1391--- PASS: TestSweepSkipsRowsLockedByPush (8.59s)1392=== CONT TestReadProxyNarinfoAlreadyDecompressed13932026/10/27 08:16:33 INFO Received uploads request method=POST path=/api/pending_closures13942026/10/27 08:16:33 INFO Aborted multipart uploads count=0 kept=013952026/10/27 08:16:33 WARN Force mode enabled - objects will be deleted immediately without grace period13962026/10/27 08:16:33 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."13972026/10/27 08:16:33 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1398--- PASS: TestFailedS3DeleteKeepsTombstone (8.38s)1399=== CONT TestPushDedupSurvivesConcurrentGC1400--- PASS: TestReadRedirectNar (8.23s)1401=== CONT TestGCAdvisoryLockBlocksConcurrentRun14022026/10/27 08:16:34 INFO Aborted multipart uploads count=0 kept=014032026/10/27 08:16:34 WARN Force mode enabled - objects will be deleted immediately without grace period14042026/10/27 08:16:34 INFO Received uploads request method=POST path=/api/pending_closures1405--- PASS: TestTombstonedObjectOfferedWithoutWaiting (8.11s)1406=== CONT TestGCBugBareHashReferences14072026/10/27 08:16:35 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=014082026/10/27 08:16:35 INFO Vacuumed table table=pending_closures14092026/10/27 08:16:35 INFO Vacuumed table table=pending_objects14102026/10/27 08:16:35 INFO Vacuumed table table=multipart_uploads14112026/10/27 08:16:35 INFO Vacuumed table table=closures1412--- PASS: TestReadProxyDisabled (7.89s)1413=== CONT TestService_ReadScope_PublicByDefault14142026/10/27 08:16:35 INFO Vacuumed table table=objects1415--- PASS: TestGCSweepDeliversEachKeyOnce (9.39s)1416=== CONT TestCacheConfigHandler1417=== RUN TestCacheConfigHandler/full_config,_no_issuer1418=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1419=== RUN TestCacheConfigHandler/no_cache_url_configured1420=== PAUSE TestCacheConfigHandler/no_cache_url_configured1421=== RUN TestCacheConfigHandler/no_signing_keys1422=== PAUSE TestCacheConfigHandler/no_signing_keys1423=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1424=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1425=== CONT TestService_AuthMiddleware_OIDC14262026/10/27 08:16:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63063/oidc14272026/10/27 08:16:35 INFO Received complete multipart upload request method=POST path=/api/multipart/complete14282026/10/27 08:16:35 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ODgyODljOTktMDZhNy00NTZiLWE4ZjUtZjk0N2EwZTcyMTY0LjE2NDZmNzU1LTA4ZTItNGZlMi1hMTZmLThjOWRhNTg5NGM4YXgxNzkzMDg4OTkzMjcwMTY4MDAw error="Get \"http://127.0.0.1:1/bucket52/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"14292026/10/27 08:16:35 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=ODgyODljOTktMDZhNy00NTZiLWE4ZjUtZjk0N2EwZTcyMTY0LjZjZDBjOGE2LWZmNTAtNDdlZS04OTdkLTlkY2NjMDEyOGQ4NngxNzkzMDg4OTkzMjEyNzI0MDAw parts=1214302026/10/27 08:16:35 INFO lead: acquired remote=192.0.2.1:123414312026/10/27 08:16:35 INFO Received cleanup request method=DELETE path=/api/pending_closures14322026/10/27 08:16:35 INFO Aborted multipart uploads count=1 kept=01433--- PASS: TestRedundantMultipartUpload (12.36s)1434=== CONT TestService_RequireScope_OIDC14352026/10/27 08:16:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63068/oidc1436--- PASS: TestCacheStatsHandler (8.14s)1437=== CONT TestService_ReadAuthMiddleware1438=== NAME TestPinProtectsFromGC1439 client_integration_test.go:778: Pinned store path: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestPinProtectsFromGC1191708740/001/store/m9aknx1vhjsalididaww9c3cd91zhxp2-pinned-file.txt1440 client_integration_test.go:779: Unpinned store path: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestPinProtectsFromGC1191708740/001/store/72qbaq1ci73mw6rzhjvbhh28fz1rvvd2-unpinned-file.txt14412026/10/27 08:16:36 INFO Received push request method=POST path=/api/pushes14422026/10/27 08:16:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14432026/10/27 08:16:36 INFO Uploading m9aknx1vhjsalididaww9c3cd91zhxp2-pinned-file.txt (128B)14442026/10/27 08:16:36 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14452026/10/27 08:16:36 WARN Failed to register uploaded object key=m9aknx1vhjsalididaww9c3cd91zhxp2.ls error="server returned 404: 404 page not found\n"14462026/10/27 08:16:36 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14472026/10/27 08:16:36 INFO Signed narinfos id=1 count=114482026/10/27 08:16:36 INFO Uploading 1 narinfos14492026/10/27 08:16:36 INFO Received complete push request method=POST path=/api/pushes/1/complete14502026/10/27 08:16:36 WARN Failed to register uploaded object key=m9aknx1vhjsalididaww9c3cd91zhxp2.narinfo error="server returned 404: 404 page not found\n"14512026/10/27 08:16:36 INFO Completed push id=1 objects=3 duration=30.831042ms14522026/10/27 08:16:36 INFO Upload complete. (276ms)14532026/10/27 08:16:36 INFO Received push request method=POST path=/api/pushes14542026/10/27 08:16:36 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14552026/10/27 08:16:36 INFO Uploading 72qbaq1ci73mw6rzhjvbhh28fz1rvvd2-unpinned-file.txt (128B)14562026/10/27 08:16:36 INFO lead: released remote=192.0.2.1:123414572026/10/27 08:16:36 WARN Failed to register uploaded object key=72qbaq1ci73mw6rzhjvbhh28fz1rvvd2.ls error="server returned 404: 404 page not found\n"14582026/10/27 08:16:36 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14592026/10/27 08:16:36 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14602026/10/27 08:16:36 INFO Signed narinfos id=2 count=114612026/10/27 08:16:36 INFO Uploading 1 narinfos14622026/10/27 08:16:36 INFO lead: acquired remote=192.0.2.1:123414632026/10/27 08:16:36 INFO Received complete push request method=POST path=/api/pushes/2/complete14642026/10/27 08:16:36 WARN Failed to register uploaded object key=72qbaq1ci73mw6rzhjvbhh28fz1rvvd2.narinfo error="server returned 404: 404 page not found\n"14652026/10/27 08:16:36 INFO Completed push id=2 objects=3 duration=855.125µs14662026/10/27 08:16:36 INFO Upload complete. (173ms)14672026/10/27 08:16:36 INFO Starting cleanup of old closures method=DELETE path=/api/closures14682026/10/27 08:16:36 INFO Garbage collection started14692026/10/27 08:16:36 INFO Aborted multipart uploads count=0 kept=014702026/10/27 08:16:36 WARN Force mode enabled - objects will be deleted immediately without grace period14712026/10/27 08:16:36 INFO Received push request method=POST path=/api/pushes14722026/10/27 08:16:37 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)14732026/10/27 08:16:37 INFO Uploading fg8jzga5phr5x1ygznc9hjanxkcqrxj9-shared-dep (136B)14742026/10/27 08:16:37 INFO Uploading 5xvz7arha52zh0m3szxpv7aaq5pfp3vm-top (264B)14752026/10/27 08:16:37 WARN Failed to register uploaded object key=fg8jzga5phr5x1ygznc9hjanxkcqrxj9.ls error="server returned 404: 404 page not found\n"14762026/10/27 08:16:37 WARN Failed to register uploaded object key=5xvz7arha52zh0m3szxpv7aaq5pfp3vm.ls error="server returned 404: 404 page not found\n"14772026/10/27 08:16:37 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"14782026/10/27 08:16:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14792026/10/27 08:16:37 WARN Failed to register uploaded object key=nar/13qll9qrpypml482fwpggnfd615myxgb1f5793gyc4gqky7348yz.nar.zst error="server returned 404: 404 page not found\n"14802026/10/27 08:16:37 INFO Signed narinfos id=1 count=214812026/10/27 08:16:37 INFO Uploading 2 narinfos14822026/10/27 08:16:37 WARN Failed to register uploaded object key=5xvz7arha52zh0m3szxpv7aaq5pfp3vm.narinfo error="server returned 404: 404 page not found\n"14832026/10/27 08:16:37 INFO Received complete push request method=POST path=/api/pushes/1/complete14842026/10/27 08:16:37 WARN Failed to register uploaded object key=fg8jzga5phr5x1ygznc9hjanxkcqrxj9.narinfo error="server returned 404: 404 page not found\n"14852026/10/27 08:16:37 INFO Completed push id=1 objects=6 duration=39.11125ms14862026/10/27 08:16:37 INFO Upload complete. (354ms)1487=== NAME TestClientSharedPathCommittedMidPush1488 client_integration_test.go:727: Retrieved narinfo from S3:1489 StorePath: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientSharedPathCommittedMidPush1964859049/001/store/fg8jzga5phr5x1ygznc9hjanxkcqrxj9-shared-dep1490 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1491 Compression: zstd1492 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821493 NarSize: 1361494 References: 1495 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1496 client_integration_test.go:727: Retrieved narinfo from S3:1497 StorePath: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientSharedPathCommittedMidPush1964859049/001/store/5xvz7arha52zh0m3szxpv7aaq5pfp3vm-top1498 URL: nar/13qll9qrpypml482fwpggnfd615myxgb1f5793gyc4gqky7348yz.nar.zst1499 Compression: zstd1500 NarHash: sha256:13qll9qrpypml482fwpggnfd615myxgb1f5793gyc4gqky7348yz1501 NarSize: 2641502 References: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientSharedPathCommittedMidPush1964859049/001/store/fg8jzga5phr5x1ygznc9hjanxkcqrxj9-shared-dep1503 CA: text:sha256:0gjcds6lj4y4xyhb87lrjps9wm5yjwpwlcp4davhccr86yc83asy1504--- PASS: TestConnectWaitsForAPeerMigration (9.60s)1505=== CONT TestService_AuthMiddleware_MTLSBoundSubjects1506--- PASS: TestClientSharedPathCommittedMidPush (8.99s)1507=== CONT TestService_AuthMiddleware_MTLSProxyHeader1508=== NAME TestClientWithDependencies1509 client_integration_test.go:660: Built derivation: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientWithDependencies1536958067/001/store/hvcmsijb1jjm2rnwx7v1rff72hskr3da-test-script1510 client_integration_test.go:662: Found 1 dependencies (including self)15112026/10/27 08:16:37 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=01512=== NAME TestClientMultipleUploads1513 client_integration_test.go:405: Created store path 0: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientMultipleUploads2756022896/001/store/fpw8549fpqhi5xipdvc924q3af7yv997-test-file-0.txt15142026/10/27 08:16:37 INFO Vacuumed table table=pending_closures15152026/10/27 08:16:37 INFO Vacuumed table table=pending_objects15162026/10/27 08:16:37 INFO Vacuumed table table=multipart_uploads15172026/10/27 08:16:37 INFO Vacuumed table table=closures1518 client_integration_test.go:405: Created store path 1: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientMultipleUploads2756022896/001/store/mrgqnp6jpaqmzhwj6djcwlvv6zxraxiz-test-file-1.txt15192026/10/27 08:16:37 INFO Received push request method=POST path=/api/pushes15202026/10/27 08:16:37 INFO Vacuumed table table=objects15212026/10/27 08:16:37 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15222026/10/27 08:16:37 INFO Uploading hvcmsijb1jjm2rnwx7v1rff72hskr3da-test-script (136B)15232026/10/27 08:16:37 WARN Failed to register uploaded object key=hvcmsijb1jjm2rnwx7v1rff72hskr3da.ls error="server returned 404: 404 page not found\n"15242026/10/27 08:16:37 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15252026/10/27 08:16:37 WARN Failed to register uploaded object key=log/hlxgyn4d51psnc546zpm0cacl1cqsb45-test-script.drv error="server returned 404: 404 page not found\n"15262026/10/27 08:16:37 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15272026/10/27 08:16:37 INFO Signed narinfos id=1 count=115282026/10/27 08:16:37 INFO Uploading 1 narinfos1529 client_integration_test.go:405: Created store path 2: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientMultipleUploads2756022896/001/store/1650hrz5c28fa087adbf4919d84f37w9-test-file-2.txt15302026/10/27 08:16:37 INFO Received complete push request method=POST path=/api/pushes/1/complete15312026/10/27 08:16:37 WARN Failed to register uploaded object key=hvcmsijb1jjm2rnwx7v1rff72hskr3da.narinfo error="server returned 404: 404 page not found\n"1532=== NAME TestClientIntegration1533 client_integration_test.go:291: Created store path: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientIntegration1092584562/002/store/x8ggmgjil5yhlwk66v9rw12ldi93chns-test-file.txt15342026/10/27 08:16:37 INFO Completed push id=1 objects=4 duration=20.476375ms15352026/10/27 08:16:37 INFO Upload complete. (301ms)1536=== NAME TestClientWithDependencies1537 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientWithDependencies1536958067/001/store) requires matching store prefix15382026/10/27 08:16:37 INFO lead: released remote=192.0.2.1:12341539--- PASS: TestLeadElectsOneAndHandsOver (10.13s)1540=== CONT TestLeadEndsOnShutdown15412026/10/27 08:16:37 INFO Received push request method=POST path=/api/pushes15422026/10/27 08:16:37 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)15432026/10/27 08:16:37 INFO Uploading fpw8549fpqhi5xipdvc924q3af7yv997-test-file-0.txt (160B)15442026/10/27 08:16:37 INFO Uploading mrgqnp6jpaqmzhwj6djcwlvv6zxraxiz-test-file-1.txt (160B)15452026/10/27 08:16:37 INFO Uploading 1650hrz5c28fa087adbf4919d84f37w9-test-file-2.txt (160B)15462026/10/27 08:16:37 INFO Received push request method=POST path=/api/pushes1547--- PASS: TestClientWithDependencies (9.32s)1548=== CONT TestLeadIncumbentAnnouncesAtOnce15492026/10/27 08:16:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15502026/10/27 08:16:38 INFO Uploading x8ggmgjil5yhlwk66v9rw12ldi93chns-test-file.txt (152B)15512026/10/27 08:16:38 WARN Failed to register uploaded object key=1650hrz5c28fa087adbf4919d84f37w9.ls error="server returned 404: 404 page not found\n"15522026/10/27 08:16:38 WARN Failed to register uploaded object key=mrgqnp6jpaqmzhwj6djcwlvv6zxraxiz.ls error="server returned 404: 404 page not found\n"15532026/10/27 08:16:38 WARN Failed to register uploaded object key=fpw8549fpqhi5xipdvc924q3af7yv997.ls error="server returned 404: 404 page not found\n"15542026/10/27 08:16:38 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"15552026/10/27 08:16:38 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"15562026/10/27 08:16:38 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"15572026/10/27 08:16:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15582026/10/27 08:16:38 INFO Signed narinfos id=1 count=315592026/10/27 08:16:38 INFO Uploading 3 narinfos15602026/10/27 08:16:38 WARN Failed to register uploaded object key=x8ggmgjil5yhlwk66v9rw12ldi93chns.ls error="server returned 404: 404 page not found\n"15612026/10/27 08:16:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15622026/10/27 08:16:38 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"15632026/10/27 08:16:38 INFO Signed narinfos id=1 count=115642026/10/27 08:16:38 INFO Uploading 1 narinfos15652026/10/27 08:16:38 WARN Failed to register uploaded object key=fpw8549fpqhi5xipdvc924q3af7yv997.narinfo error="server returned 404: 404 page not found\n"15662026/10/27 08:16:38 WARN Failed to register uploaded object key=mrgqnp6jpaqmzhwj6djcwlvv6zxraxiz.narinfo error="server returned 404: 404 page not found\n"15672026/10/27 08:16:38 INFO Received complete push request method=POST path=/api/pushes/1/complete15682026/10/27 08:16:38 WARN Failed to register uploaded object key=1650hrz5c28fa087adbf4919d84f37w9.narinfo error="server returned 404: 404 page not found\n"15692026/10/27 08:16:38 INFO Received complete push request method=POST path=/api/pushes/1/complete15702026/10/27 08:16:38 WARN Failed to register uploaded object key=x8ggmgjil5yhlwk66v9rw12ldi93chns.narinfo error="server returned 404: 404 page not found\n"15712026/10/27 08:16:38 INFO Completed push id=1 objects=9 duration=31.027959ms15722026/10/27 08:16:38 INFO Upload complete. (380ms)1573=== NAME TestClientMultipleUploads1574 client_integration_test.go:416: Uploaded 3 paths in 413.884542ms15752026/10/27 08:16:38 INFO Completed push id=1 objects=3 duration=29.363917ms15762026/10/27 08:16:38 INFO Upload complete. (325ms)15772026/10/27 08:16:38 INFO All 1 paths already cached1578=== NAME TestClientIntegration1579 client_integration_test.go:317: Retrieved narinfo from S3:1580--- PASS: TestClientMultipleUploads (8.60s)1581=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1582=== NAME TestClientIntegration1583 StorePath: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientIntegration1092584562/002/store/x8ggmgjil5yhlwk66v9rw12ldi93chns-test-file.txt1584 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1585 Compression: zstd1586 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11587 NarSize: 1521588 References: 1589 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11590 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1591 client_integration_test.go:318: Decompressed .ls content (64 bytes):1592 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1593=== NAME TestClientCADerivations1594 client_ca_test.go:136: Built CA derivation: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientCADerivations2064772308/001/store/nqall4pkybjdgka9g7y648rzza6sfim1-ca-test1595 client_ca_test.go:139: Found 1 dependencies (including self)15962026/10/27 08:16:38 INFO Received push request method=POST path=/api/pushes15972026/10/27 08:16:38 INFO Object in database but missing from S3 key=x8ggmgjil5yhlwk66v9rw12ldi93chns.ls15982026/10/27 08:16:38 WARN Found objects in DB but missing from S3, will re-upload count=115992026/10/27 08:16:38 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16002026/10/27 08:16:38 INFO Received complete push request method=POST path=/api/pushes/2/complete16012026/10/27 08:16:38 WARN Failed to register uploaded object key=x8ggmgjil5yhlwk66v9rw12ldi93chns.ls error="server returned 404: 404 page not found\n"16022026/10/27 08:16:38 INFO Completed push id=2 objects=3 duration=50.374916ms16032026/10/27 08:16:38 INFO Upload complete. (163ms)1604=== NAME TestClientIntegration1605 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1606 client_integration_test.go:335: Decompressed .ls content (49 bytes):16072026/10/27 08:16:38 INFO Received push request method=POST path=/api/pushes1608 {"version":1,"root":{"type":"regular","size":39}}16092026/10/27 08:16:38 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16102026/10/27 08:16:38 INFO Uploading nqall4pkybjdgka9g7y648rzza6sfim1-ca-test (144B)16112026/10/27 08:16:38 WARN Failed to register uploaded object key=nqall4pkybjdgka9g7y648rzza6sfim1.ls error="server returned 404: 404 page not found\n"16122026/10/27 08:16:38 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"16132026/10/27 08:16:38 WARN Failed to register uploaded object key=log/qwh8nki1gkhlv5m473s1w0s6ymq4nbvd-ca-test.drv error="server returned 404: 404 page not found\n"16142026/10/27 08:16:38 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16152026/10/27 08:16:38 INFO Signed narinfos id=1 count=116162026/10/27 08:16:38 INFO Uploading 1 narinfos16172026/10/27 08:16:38 INFO Received complete push request method=POST path=/api/pushes/1/complete16182026/10/27 08:16:38 WARN Failed to register uploaded object key=nqall4pkybjdgka9g7y648rzza6sfim1.narinfo error="server returned 404: 404 page not found\n"16192026/10/27 08:16:38 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=016202026/10/27 08:16:38 INFO Completed push id=1 objects=4 duration=45.904958ms16212026/10/27 08:16:38 INFO Upload complete. (327ms)16222026/10/27 08:16:38 INFO Received create pin request method=POST path=/api/pins/myapp1623=== NAME TestClientCADerivations1624 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientCADerivations2064772308/001/store/nqall4pkybjdgka9g7y648rzza6sfim1-ca-test1625 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1626 Compression: zstd1627 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1628 NarSize: 1441629 References: 1630 Deriver: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientCADerivations2064772308/001/store/qwh8nki1gkhlv5m473s1w0s6ymq4nbvd-ca-test.drv1631 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1632 client_ca_test.go:185: Checking for realisation files in S3...1633 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1634 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache16352026/10/27 08:16:39 INFO Created/updated pin name=myapp store_path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestPinProtectsFromGC1191708740/001/store/m9aknx1vhjsalididaww9c3cd91zhxp2-pinned-file.txt narinfo_key=m9aknx1vhjsalididaww9c3cd91zhxp2.narinfo16362026/10/27 08:16:39 INFO Starting cleanup of old closures method=DELETE path=/api/closures16372026/10/27 08:16:39 INFO Garbage collection started16382026/10/27 08:16:39 INFO Aborted multipart uploads count=0 kept=016392026/10/27 08:16:39 WARN Force mode enabled - objects will be deleted immediately without grace period16402026/10/27 08:16:39 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016412026/10/27 08:16:39 INFO Vacuumed table table=pending_closures16422026/10/27 08:16:39 INFO Vacuumed table table=pending_objects16432026/10/27 08:16:39 INFO Vacuumed table table=multipart_uploads16442026/10/27 08:16:39 INFO Vacuumed table table=closures16452026/10/27 08:16:39 INFO Vacuumed table table=objects1646 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket71?endpoint=http://localhost:62772®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientCADerivations2064772308/001/store'16472026/10/27 08:16:39 INFO Received push request method=POST path=/api/pushes1648 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 116492026/10/27 08:16:39 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)16502026/10/27 08:16:39 INFO Received complete push request method=POST path=/api/pushes/3/complete16512026/10/27 08:16:39 WARN Failed to register uploaded object key=x8ggmgjil5yhlwk66v9rw12ldi93chns.ls error="server returned 404: 404 page not found\n"16522026/10/27 08:16:39 INFO Completed push id=3 objects=3 duration=781.542µs16532026/10/27 08:16:39 INFO Upload complete. (115ms)1654=== NAME TestClientIntegration1655 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1656 client_integration_test.go:352: Decompressed .ls content (49 bytes):1657 {"version":1,"root":{"type":"regular","size":39}}1658 client_integration_test.go:363: Testing garbage collection...1659--- PASS: TestClientCADerivations (8.80s)16602026/10/27 08:16:39 INFO Starting cleanup of old closures method=DELETE path=/api/closures1661=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh16622026/10/27 08:16:39 INFO Garbage collection started16632026/10/27 08:16:39 INFO Aborted multipart uploads count=0 kept=016642026/10/27 08:16:39 WARN Force mode enabled - objects will be deleted immediately without grace period16652026/10/27 08:16:39 INFO Aborted multipart uploads count=0 kept=016662026/10/27 08:16:39 WARN Force mode enabled - objects will be deleted immediately without grace period16672026/10/27 08:16:39 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=016682026/10/27 08:16:39 INFO Vacuumed table table=pending_closures16692026/10/27 08:16:39 INFO Vacuumed table table=pending_objects16702026/10/27 08:16:39 INFO Vacuumed table table=multipart_uploads16712026/10/27 08:16:39 INFO Vacuumed table table=closures16722026/10/27 08:16:39 INFO Vacuumed table table=objects1673--- PASS: TestGCMetrics (7.02s)1674=== CONT TestParseSingleRange/none1675=== CONT TestParseSingleRange/open-ended1676=== CONT TestParseSingleRange/start_far_past_EOF1677=== CONT TestParseSingleRange/start_past_EOF1678=== CONT TestParseSingleRange/single_byte1679=== CONT TestParseSingleRange/suffix_exceeds_size1680=== CONT TestParseSingleRange/suffix1681=== CONT TestParseSingleRange/end_clamped_to_size1682=== CONT TestParseSingleRange/malformed_both_empty1683=== CONT TestParseSingleRange/closed1684=== CONT TestParseSingleRange/malformed_end_before_start1685=== CONT TestParseSingleRange/multi-range_ignored1686=== CONT TestParseSingleRange/malformed_no_dash1687=== CONT TestParseSingleRange/unknown_unit1688--- PASS: TestParseSingleRange (0.00s)1689 --- PASS: TestParseSingleRange/none (0.00s)1690 --- PASS: TestParseSingleRange/open-ended (0.00s)1691 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1692 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1693 --- PASS: TestParseSingleRange/single_byte (0.00s)1694 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1695 --- PASS: TestParseSingleRange/suffix (0.00s)1696 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1697 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1698 --- PASS: TestParseSingleRange/closed (0.00s)1699 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1700 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1701 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1702 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1703=== CONT TestServerTLSConfig/no_client_CA1704=== CONT TestServerTLSConfig/not_a_PEM_file1705=== CONT TestServerTLSConfig/missing_CA_file1706--- PASS: TestServerTLSConfig (0.00s)1707 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1708 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1709 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1710=== CONT TestIsValidCachePath/narinfo1711=== CONT TestIsValidCachePath/index.html1712=== CONT TestIsValidCachePath/short_hash1713=== CONT TestIsValidCachePath/wrong_extension1714=== CONT TestIsValidCachePath/leading_slash1715=== CONT TestIsValidCachePath/empty1716=== CONT TestIsValidCachePath/random_path1717=== CONT TestIsValidCachePath/invalid_char_u1718=== CONT TestIsValidCachePath/invalid_char_e1719=== CONT TestIsValidCachePath/traversal_in_middle1720=== CONT TestIsValidCachePath/traversal_parent1721=== CONT TestIsValidCachePath/realisation1722=== CONT TestIsValidCachePath/nix-cache-info1723=== CONT TestIsValidCachePath/nar_xz1724=== CONT TestIsValidCachePath/nar_zst1725=== CONT TestIsValidCachePath/nar_uncompressed1726=== CONT TestIsValidCachePath/nar_bz21727=== CONT TestIsValidCachePath/ls1728=== CONT TestIsValidCachePath/log1729=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1730--- PASS: TestIsValidCachePath (0.00s)1731 --- PASS: TestIsValidCachePath/narinfo (0.00s)1732 --- PASS: TestIsValidCachePath/index.html (0.00s)1733 --- PASS: TestIsValidCachePath/short_hash (0.00s)1734 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1735 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1736 --- PASS: TestIsValidCachePath/empty (0.00s)1737 --- PASS: TestIsValidCachePath/random_path (0.00s)1738 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1739 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1740 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1741 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1742 --- PASS: TestIsValidCachePath/realisation (0.00s)1743 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1744 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1745 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1746 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1747 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1748 --- PASS: TestIsValidCachePath/ls (0.00s)1749 --- PASS: TestIsValidCachePath/log (0.00s)1750 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1751=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17522026/10/27 08:16:39 INFO Received uploads request method=POST path=/17532026/10/27 08:16:39 INFO Received uploads request method=POST path=/api/pending_closures17542026/10/27 08:16:39 INFO Received uploads request method=POST path=/api/pending_closures17552026/10/27 08:16:39 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)17562026/10/27 08:16:39 INFO Uploading mc7qy4h0js68c435kqmj19mbyzwmk87a-shared-dep (136B)17572026/10/27 08:16:39 INFO Uploading 87li2sw8rwdg48i203d9vz54p45kgp0m-b (256B)17582026/10/27 08:16:39 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=01759--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (8.64s)1760=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17612026/10/27 08:16:39 INFO Received request for more parts method=POST path=/1762=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17632026/10/27 08:16:39 INFO Received complete multipart upload request method=POST path=/1764=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17652026/10/27 08:16:39 WARN Failed to register uploaded object key=6j39raw60vw06vnp5scvbv9v9wci2k3n.ls error="server returned 404: 404 page not found\n"17662026/10/27 08:16:39 INFO Vacuumed table table=pending_closures17672026/10/27 08:16:39 INFO Received uploads request method=POST path=/1768=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17692026/10/27 08:16:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1770--- PASS: TestUploadHandlersRejectOversizedBody (0.03s)1771 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.28s)1772 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.02s)1773 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)17742026/10/27 08:16:39 WARN Failed to register uploaded object key=87li2sw8rwdg48i203d9vz54p45kgp0m.ls error="server returned 404: 404 page not found\n"1775=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17762026/10/27 08:16:39 INFO Received complete multipart upload request method=POST path=/1777=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17782026/10/27 08:16:39 WARN Failed to register uploaded object key=mc7qy4h0js68c435kqmj19mbyzwmk87a.ls error="server returned 404: 404 page not found\n"17792026/10/27 08:16:39 INFO Received request for more parts method=POST path=/1780=== CONT TestIsValidUploadKey/narinfo17812026/10/27 08:16:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign1782=== CONT TestIsValidUploadKey/realisation_plus_in_output1783=== CONT TestIsValidUploadKey/unknown_type1784=== CONT TestIsValidUploadKey/empty_key1785=== CONT TestIsValidUploadKey/absolute1786=== CONT TestIsValidUploadKey/traversal_nar1787=== CONT TestIsValidUploadKey/traversal1788=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1789=== CONT TestIsValidUploadKey/nar_key,_narinfo_type17902026/10/27 08:16:39 WARN Failed to register uploaded object key=nar/010hgbjgy3pxbckj0ldllrs8xy1ky8wvbvyxwjkhbi0ikrn8nrrs.nar.zst error="server returned 404: 404 page not found\n"17912026/10/27 08:16:39 INFO Received uploads request method=POST path=/1792=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1793--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1794 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.02s)1795 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.01s)1796 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.01s)1797 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.01s)1798=== CONT TestIsValidUploadKey/index.html1799=== CONT TestIsValidUploadKey/build_log_home-manager_file1800=== CONT TestIsValidUploadKey/realisation1801=== CONT TestIsValidUploadKey/build_log_equals1802=== CONT TestIsValidUploadKey/build_log_question_mark1803=== CONT TestIsValidUploadKey/build_log_plus_in_name18042026/10/27 08:16:39 INFO Signed narinfos id=1 count=21805=== CONT TestIsValidUploadKey/nar_plain1806=== CONT TestIsValidUploadKey/build_log18072026/10/27 08:16:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign1808=== CONT TestIsValidUploadKey/listing1809=== CONT TestIsValidUploadKey/nar_xz1810=== CONT TestIsValidUploadKey/nar_zst1811=== CONT TestIsValidUploadKey/nix-cache-info1812--- PASS: TestIsValidUploadKey (0.02s)1813 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1814 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1815 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1816 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1817 --- PASS: TestIsValidUploadKey/absolute (0.00s)1818 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1819 --- PASS: TestIsValidUploadKey/traversal (0.00s)1820 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1821 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1822 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1823 --- PASS: TestIsValidUploadKey/index.html (0.00s)1824 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1825 --- PASS: TestIsValidUploadKey/realisation (0.00s)1826 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1827 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1828 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1829 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1830 --- PASS: TestIsValidUploadKey/build_log (0.00s)1831 --- PASS: TestIsValidUploadKey/listing (0.00s)1832 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1833 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1834 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1835=== CONT TestPendingClosureWriteTimeout/empty1836=== CONT TestPendingClosureWriteTimeout/670k_objects1837=== CONT TestPendingClosureWriteTimeout/400_objects1838=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1839=== CONT TestGCEndsOnShutdown/before_the_run18402026/10/27 08:16:39 INFO Signed narinfos id=2 count=218412026/10/27 08:16:39 INFO Vacuumed table table=pending_objects18422026/10/27 08:16:39 INFO Uploading 4 narinfos18432026/10/27 08:16:39 INFO Vacuumed table table=multipart_uploads18442026/10/27 08:16:39 WARN Failed to register uploaded object key=mc7qy4h0js68c435kqmj19mbyzwmk87a.narinfo error="server returned 404: 404 page not found\n"18452026/10/27 08:16:39 WARN Failed to register uploaded object key=87li2sw8rwdg48i203d9vz54p45kgp0m.narinfo error="server returned 404: 404 page not found\n"18462026/10/27 08:16:39 INFO Vacuumed table table=closures18472026/10/27 08:16:39 WARN Failed to register uploaded object key=6j39raw60vw06vnp5scvbv9v9wci2k3n.narinfo error="server returned 404: 404 page not found\n"18482026/10/27 08:16:39 INFO Vacuumed table table=objects18492026/10/27 08:16:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete18502026/10/27 08:16:39 WARN Failed to register uploaded object key=mc7qy4h0js68c435kqmj19mbyzwmk87a.narinfo error="server returned 404: 404 page not found\n"18512026/10/27 08:16:39 INFO Completed upload id=1 objects=6 duration=17.754375ms18522026/10/27 08:16:39 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete18532026/10/27 08:16:39 INFO Completed upload id=2 objects=6 duration=561.542µs18542026/10/27 08:16:39 INFO Upload complete. (488ms)1855=== NAME TestClientFallsBackToClosures1856 client_pushes_test.go:112: Retrieved narinfo from S3:1857 StorePath: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientFallsBackToClosures4161176390/001/store/mc7qy4h0js68c435kqmj19mbyzwmk87a-shared-dep1858 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1859 Compression: zstd1860 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821861 NarSize: 1361862 References: 1863 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1864 client_pushes_test.go:112: Retrieved narinfo from S3:1865 StorePath: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientFallsBackToClosures4161176390/001/store/6j39raw60vw06vnp5scvbv9v9wci2k3n-a1866 URL: nar/010hgbjgy3pxbckj0ldllrs8xy1ky8wvbvyxwjkhbi0ikrn8nrrs.nar.zst1867 Compression: zstd1868 NarHash: sha256:010hgbjgy3pxbckj0ldllrs8xy1ky8wvbvyxwjkhbi0ikrn8nrrs1869 NarSize: 2561870 References: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientFallsBackToClosures4161176390/001/store/mc7qy4h0js68c435kqmj19mbyzwmk87a-shared-dep1871 CA: text:sha256:0d9ckl9mvfgq2sy3738nzy24ix8di0la1n1wb34l19xlbrc2ycf11872 client_pushes_test.go:112: Retrieved narinfo from S3:1873 StorePath: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientFallsBackToClosures4161176390/001/store/87li2sw8rwdg48i203d9vz54p45kgp0m-b1874 URL: nar/010hgbjgy3pxbckj0ldllrs8xy1ky8wvbvyxwjkhbi0ikrn8nrrs.nar.zst1875 Compression: zstd1876 NarHash: sha256:010hgbjgy3pxbckj0ldllrs8xy1ky8wvbvyxwjkhbi0ikrn8nrrs1877 NarSize: 2561878 References: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientFallsBackToClosures4161176390/001/store/mc7qy4h0js68c435kqmj19mbyzwmk87a-shared-dep1879 CA: text:sha256:0d9ckl9mvfgq2sy3738nzy24ix8di0la1n1wb34l19xlbrc2ycf11880--- PASS: TestClientFallsBackToClosures (8.57s)1881=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark18822026/10/27 08:16:40 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1883--- PASS: TestReadProxyNarinfo (7.49s)1884=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete18852026/10/27 08:16:40 INFO Received push request method=POST path=/api/pushes18862026/10/27 08:16:40 INFO Received uploads request method=POST path=/api/pending_closures18872026/10/27 08:16:40 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)18882026/10/27 08:16:40 INFO Uploading wcmv23wmlxjyn92691n0q73jbxs1m8mr-shared-dep (136B)18892026/10/27 08:16:40 INFO Uploading 16nchry9hh7139l9bg1lgpdi7n7j1bhi-b (256B)18902026/10/27 08:16:40 WARN Failed to register uploaded object key=nar/0brlyrk1gir6x06frzzkvn9hb068681972wdbri8p301d2ni1r1c.nar.zst error="server returned 404: 404 page not found\n"18912026/10/27 08:16:40 WARN Failed to register uploaded object key=wfv68fkaylbj2xc6v0m9kn7p9q953qlk.ls error="server returned 404: 404 page not found\n"18922026/10/27 08:16:40 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"18932026/10/27 08:16:40 WARN Failed to register uploaded object key=wcmv23wmlxjyn92691n0q73jbxs1m8mr.ls error="server returned 404: 404 page not found\n"18942026/10/27 08:16:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18952026/10/27 08:16:40 WARN Failed to register uploaded object key=16nchry9hh7139l9bg1lgpdi7n7j1bhi.ls error="server returned 404: 404 page not found\n"18962026/10/27 08:16:40 INFO Signed narinfos id=1 count=318972026/10/27 08:16:40 INFO Uploading 3 narinfos1898--- PASS: TestDeduplicatedObjectsRecordedAsPending (7.03s)1899=== CONT TestProxyWriteTimeout/narinfo1900=== CONT TestProxyWriteTimeout/10_GiB_nar1901=== CONT TestProxyWriteTimeout/unknown_size19022026/10/27 08:16:40 WARN Failed to register uploaded object key=16nchry9hh7139l9bg1lgpdi7n7j1bhi.narinfo error="server returned 404: 404 page not found\n"1903=== CONT TestProxyWriteTimeout/1_GiB_nar19042026/10/27 08:16:40 WARN Failed to register uploaded object key=wfv68fkaylbj2xc6v0m9kn7p9q953qlk.narinfo error="server returned 404: 404 page not found\n"1905=== CONT TestPush_RejectsBadRequests/bad_root19062026/10/27 08:16:40 INFO Received push request method=POST path=/api/pushes1907--- PASS: TestProxyWriteTimeout (0.00s)1908 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1909 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1910 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1911 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1912=== CONT TestPush_RejectsBadRequests/root_not_in_objects19132026/10/27 08:16:40 INFO Received push request method=POST path=/api/pushes19142026/10/27 08:16:40 INFO Received complete push request method=POST path=/api/pushes/1/complete1915=== CONT TestPush_RejectsBadRequests/no_objects19162026/10/27 08:16:40 INFO Received push request method=POST path=/api/pushes1917=== CONT TestPush_RejectsBadRequests/no_roots19182026/10/27 08:16:40 INFO Received push request method=POST path=/api/pushes1919--- PASS: TestPush_RejectsBadRequests (5.82s)1920 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1921 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1922 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1923 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1924=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows19252026/10/27 08:16:40 WARN Failed to register uploaded object key=wcmv23wmlxjyn92691n0q73jbxs1m8mr.narinfo error="server returned 404: 404 page not found\n"19262026/10/27 08:16:40 INFO Completed push id=1 objects=8 duration=25.210209ms19272026/10/27 08:16:40 INFO Upload complete. (303ms)1928=== NAME TestClientPushesUseOnePush1929 client_pushes_test.go:97: Retrieved narinfo from S3:1930 StorePath: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientPushesUseOnePush3666978373/001/store/wcmv23wmlxjyn92691n0q73jbxs1m8mr-shared-dep1931 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1932 Compression: zstd1933 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821934 NarSize: 1361935 References: 1936 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1937 client_pushes_test.go:97: Retrieved narinfo from S3:1938 StorePath: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientPushesUseOnePush3666978373/001/store/wfv68fkaylbj2xc6v0m9kn7p9q953qlk-a1939 URL: nar/0brlyrk1gir6x06frzzkvn9hb068681972wdbri8p301d2ni1r1c.nar.zst1940 Compression: zstd1941 NarHash: sha256:0brlyrk1gir6x06frzzkvn9hb068681972wdbri8p301d2ni1r1c1942 NarSize: 2561943 References: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientPushesUseOnePush3666978373/001/store/wcmv23wmlxjyn92691n0q73jbxs1m8mr-shared-dep1944 CA: text:sha256:1s0qggzldrks0058hybz21izarr05j568vg6simfq5im4ykn07jw1945 client_pushes_test.go:97: Retrieved narinfo from S3:1946 StorePath: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientPushesUseOnePush3666978373/001/store/16nchry9hh7139l9bg1lgpdi7n7j1bhi-b1947 URL: nar/0brlyrk1gir6x06frzzkvn9hb068681972wdbri8p301d2ni1r1c.nar.zst1948 Compression: zstd1949 NarHash: sha256:0brlyrk1gir6x06frzzkvn9hb068681972wdbri8p301d2ni1r1c1950 NarSize: 2561951 References: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestClientPushesUseOnePush3666978373/001/store/wcmv23wmlxjyn92691n0q73jbxs1m8mr-shared-dep1952 CA: text:sha256:1s0qggzldrks0058hybz21izarr05j568vg6simfq5im4ykn07jw1953--- PASS: TestClientPushesUseOnePush (8.50s)1954=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check1955--- PASS: TestReadProxyNarinfoAlreadyDecompressed (7.24s)1956=== CONT TestResolveDBConnectionString/flag_wins1957=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1958=== CONT TestResolveDBConnectionString/nothing_configured1959=== CONT TestResolveDBConnectionString/missing_file_is_an_error1960=== CONT TestResolveDBConnectionString/file_when_flag_empty1961=== CONT TestClientErrorHandling/InvalidStorePath1962--- PASS: TestResolveDBConnectionString (0.04s)1963 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1964 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1965 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1966 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1967 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)19682026/10/27 08:16:41 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld4 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1969--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (6.98s)1970=== CONT TestClientErrorHandling/ServerNotAvailable1971=== NAME TestPinProtectsFromGC1972 client_integration_test.go:887: Pin successfully protected closure from garbage collection1973--- PASS: TestPinProtectsFromGC (13.43s)1974=== CONT TestClientErrorHandling/InvalidAuthToken19752026/10/27 08:16:41 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=01976=== NAME TestClientIntegration1977 client_integration_test.go:370: Objects in database after GC:1978 client_integration_test.go:370: Successfully deleted all objects with GC --force1979--- PASS: TestClientIntegration (11.27s)1980=== CONT TestCacheConfigHandler/full_config,_no_issuer1981=== CONT TestCacheConfigHandler/no_signing_keys1982=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1983=== CONT TestCacheConfigHandler/no_cache_url_configured1984--- PASS: TestCacheConfigHandler (0.00s)1985 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1986 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1987 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1988 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)19892026/10/27 08:16:41 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/present19902026/10/27 08:16:41 INFO Received uploads request method=POST path=/api/pending_closures19912026/10/27 08:16:41 WARN Request failed, retrying attempt=2 backoff=210.702203ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19922026/10/27 08:16:41 INFO Aborted multipart uploads count=0 kept=019932026/10/27 08:16:41 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=019942026/10/27 08:16:41 INFO Vacuumed table table=pending_closures19952026/10/27 08:16:41 WARN Request failed, retrying attempt=3 backoff=395.32172ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19962026/10/27 08:16:41 INFO Vacuumed table table=pending_objects19972026/10/27 08:16:41 INFO Vacuumed table table=multipart_uploads19982026/10/27 08:16:41 INFO Vacuumed table table=closures19992026/10/27 08:16:41 INFO Vacuumed table table=objects20002026/10/27 08:16:41 INFO Aborted multipart uploads count=0 kept=020012026/10/27 08:16:41 WARN Force mode enabled - objects will be deleted immediately without grace period20022026/10/27 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=020032026/10/27 08:16:41 INFO Vacuumed table table=pending_closures20042026/10/27 08:16:41 INFO Vacuumed table table=pending_objects20052026/10/27 08:16:41 INFO Vacuumed table table=multipart_uploads2006--- PASS: TestGCBugBareHashReferences (7.02s)20072026/10/27 08:16:41 INFO Vacuumed table table=closures20082026/10/27 08:16:41 INFO Vacuumed table table=objects2009--- PASS: TestPushDedupSurvivesConcurrentGC (7.99s)2010--- PASS: TestService_ReadScope_PublicByDefault (6.69s)20112026/10/27 08:16:42 WARN Request failed, retrying attempt=4 backoff=723.974892ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2012=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token2013=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token2014=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2015=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2016=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected2017=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2018=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2019=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2020=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2021=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20222026/10/27 08:16:42 WARN Authentication failed token_preview=not-a-valid-jwt token_length=15 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]2023=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2024=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20252026/10/27 08:16:42 WARN Authentication failed token_preview=eyJhbGciOi...hpWKA5BgGQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2026--- PASS: TestService_AuthMiddleware_OIDC (6.93s)2027 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2028 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2029 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2030 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2031=== RUN TestService_RequireScope_OIDC/builder_may_write2032=== PAUSE TestService_RequireScope_OIDC/builder_may_write2033=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2034=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2035=== RUN TestService_RequireScope_OIDC/ops_may_admin2036=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2037=== RUN TestService_RequireScope_OIDC/ops_may_not_write2038=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2039=== RUN TestService_RequireScope_OIDC/reader_may_not_write2040=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2041=== RUN TestService_RequireScope_OIDC/static_token_may_admin2042=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2043=== RUN TestService_RequireScope_OIDC/static_token_may_write2044=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2045=== RUN TestService_RequireScope_OIDC/reader_may_read2046=== PAUSE TestService_RequireScope_OIDC/reader_may_read2047=== RUN TestService_RequireScope_OIDC/writer_implies_read2048=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2049=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2050=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2051=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc2052=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc2053=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2054=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2055=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2056=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2057=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2058=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2059=== CONT TestService_RequireScope_OIDC/builder_may_write2060=== CONT TestService_RequireScope_OIDC/reader_may_read2061=== CONT TestService_RequireScope_OIDC/reader_may_not_write2062=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2063=== CONT TestService_RequireScope_OIDC/static_token_may_write2064=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2065=== CONT TestService_RequireScope_OIDC/ops_may_admin20662026/10/27 08:16:42 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]2067=== CONT TestService_RequireScope_OIDC/static_token_may_admin2068=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2069=== CONT TestService_RequireScope_OIDC/ops_may_not_write2070=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2071=== CONT TestService_RequireScope_OIDC/writer_implies_read2072=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2073=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2074--- PASS: TestService_RequireScope_OIDC (7.00s)2075 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2076 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2077 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2078 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2079 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2080 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2081 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2082 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2083 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2084 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2085 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2086 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2087 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2088 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)20892026/10/27 08:16:42 WARN Request failed, retrying attempt=5 backoff=1.639002031s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2090--- PASS: TestService_ReadAuthMiddleware (6.64s)20912026/10/27 08:16:43 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20922026/10/27 08:16:43 WARN mTLS auth: bound subjects configured but subject DN unavailable20932026/10/27 08:16:43 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2094--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (5.82s)2095--- PASS: TestDeleteClosuresRacingPins (12.09s)2096--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.02s)20972026/10/27 08:16:43 INFO lead: acquired remote=192.0.2.1:123420982026/10/27 08:16:43 INFO lead: released remote=192.0.2.1:12342099--- PASS: TestLeadIncumbentAnnouncesAtOnce (5.65s)21002026/10/27 08:16:43 INFO lead: acquired remote=192.0.2.1:123421012026/10/27 08:16:44 INFO Received uploads request method=POST path=/api/pending_closures21022026/10/27 08:16:44 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-config21032026/10/27 08:16:44 WARN Request failed, retrying attempt=2 backoff=214.703614ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2104--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2105 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (6.27s)2106 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (5.59s)21072026/10/27 08:16:44 WARN Request failed, retrying attempt=3 backoff=376.515196ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21082026/10/27 08:16:44 INFO lead: released remote=192.0.2.1:12342109--- PASS: TestLeadEndsOnShutdown (6.97s)21102026/10/27 08:16:45 INFO Aborted multipart uploads count=0 kept=021112026/10/27 08:16:45 WARN Force mode enabled - objects will be deleted immediately without grace period21122026/10/27 08:16:45 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:62772/bucket95/?delete=\": context canceled"21132026/10/27 08:16:45 INFO Aborted multipart uploads count=0 kept=021142026/10/27 08:16:45 WARN Force mode enabled - objects will be deleted immediately without grace period21152026/10/27 08:16:45 WARN Request failed, retrying attempt=4 backoff=858.926444ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2116--- PASS: TestGCEndsOnShutdown (0.00s)2117 --- PASS: TestGCEndsOnShutdown/before_the_run (5.07s)2118 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (4.93s)2119 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (5.25s)2120--- PASS: TestPendingClosureWriteTimeout (0.00s)2121 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2122 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2123 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2124 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (5.58s)21252026/10/27 08:16:45 INFO Received uploads request method=POST path=/api/pending_closures21262026/10/27 08:16:45 INFO Aborted multipart uploads count=0 kept=021272026/10/27 08:16:45 WARN Force mode enabled - objects will be deleted immediately without grace period21282026/10/27 08:16:45 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/10/27 08:16:45 INFO Vacuumed table table=pending_closures21302026/10/27 08:16:45 INFO Vacuumed table table=pending_objects21312026/10/27 08:16:45 INFO Vacuumed table table=multipart_uploads21322026/10/27 08:16:45 INFO Vacuumed table table=closures21332026/10/27 08:16:45 INFO Vacuumed table table=objects21342026/10/27 08:16:46 WARN Request failed, retrying attempt=5 backoff=1.697942228s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21352026/10/27 08:16:47 INFO Received uploads request method=POST path=/api/pending_closures21362026/10/27 08:16:47 INFO Aborted multipart uploads count=0 kept=021372026/10/27 08:16:47 WARN Force mode enabled - objects will be deleted immediately without grace period21382026/10/27 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=021392026/10/27 08:16:47 INFO Vacuumed table table=pending_closures21402026/10/27 08:16:47 INFO Vacuumed table table=pending_objects21412026/10/27 08:16:47 INFO Vacuumed table table=multipart_uploads21422026/10/27 08:16:47 INFO Vacuumed table table=closures21432026/10/27 08:16:47 INFO Vacuumed table table=objects2144--- PASS: TestForceGCDuringPushOffersSweptObject (0.01s)2145 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (5.84s)2146 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (7.00s)21472026/10/27 08:16:47 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"21482026/10/27 08:16:47 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-config21492026/10/27 08:16:47 WARN Request failed, retrying attempt=2 backoff=209.873079ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21502026/10/27 08:16:48 WARN Request failed, retrying attempt=3 backoff=392.23303ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21512026/10/27 08:16:48 WARN Request failed, retrying attempt=4 backoff=870.654475ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21522026/10/27 08:16:48 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21532026/10/27 08:16:48 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"21542026/10/27 08:16:49 WARN Request failed, retrying attempt=5 backoff=1.749583364s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2155=== NAME TestOrphanedObjectsGCStressTest2156 orphaned_objects_gc_test.go:503: Stress test completed successfully:2157 orphaned_objects_gc_test.go:504: - Active objects preserved: 202158 orphaned_objects_gc_test.go:505: - Objects deleted: 2102159 orphaned_objects_gc_test.go:506: - Total GC'd: 2102160--- PASS: TestOrphanedObjectsGCStressTest (34.88s)21612026/10/27 08:16:51 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21622026/10/27 08:16:51 WARN Request failed, retrying attempt=2 backoff=186.727849ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21632026/10/27 08:16:51 WARN Request failed, retrying attempt=3 backoff=411.800318ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21642026/10/27 08:16:51 WARN Request failed, retrying attempt=4 backoff=868.94478ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures21652026/10/27 08:16:52 WARN Request failed, retrying attempt=5 backoff=1.572339511s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2166--- PASS: TestClientErrorHandling (0.00s)2167 --- PASS: TestClientErrorHandling/InvalidStorePath (5.45s)2168 --- PASS: TestClientErrorHandling/InvalidAuthToken (7.91s)2169 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.33s)2170PASS2171{"timestamp":"2026-10-27T08:16:54.357342Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:63150","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(8)"}2172{"timestamp":"2026-10-27T08:16:54.357414Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:63149","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(8)"}2173{"timestamp":"2026-10-27T08:16:54.357446Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:63000","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}21742026-10-27 08:16:54.463 UTC [68287] LOG: received smart shutdown request21752026-10-27 08:16:54.464 UTC [68287] LOG: background worker "logical replication launcher" (PID 68297) exited with exit code 121762026-10-27 08:16:54.469 UTC [68292] LOG: shutting down21772026-10-27 08:16:54.469 UTC [68292] LOG: checkpoint starting: shutdown immediate21782026-10-27 08:16:55.714 UTC [68292] LOG: checkpoint complete: wrote 11478 buffers (70.1%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 31 recycled; write=0.537 s, sync=0.661 s, total=1.245 s; sync files=34045, longest=0.001 s, average=0.001 s; distance=502019 kB, estimate=502019 kB; lsn=0/201CDE88, redo lsn=0/201CDE8821792026-10-27 08:16:55.722 UTC [68287] LOG: database system is shut down2180Running OIDC tests...2181=== RUN TestAudienceForIssuer2182=== PAUSE TestAudienceForIssuer2183=== RUN TestGlobMatch2184=== PAUSE TestGlobMatch2185=== RUN TestValidateToken_ValidToken2186=== PAUSE TestValidateToken_ValidToken2187=== RUN TestValidateToken_WrongAudience2188=== PAUSE TestValidateToken_WrongAudience2189=== RUN TestValidateToken_Expired2190=== PAUSE TestValidateToken_Expired2191=== RUN TestValidateToken_BoundClaimsMismatch2192=== PAUSE TestValidateToken_BoundClaimsMismatch2193=== RUN TestValidateToken_BoundSubjectMismatch2194=== PAUSE TestValidateToken_BoundSubjectMismatch2195=== RUN TestValidateToken_MultipleProviders2196=== PAUSE TestValidateToken_MultipleProviders2197=== RUN TestValidateToken_NoMatchingProvider2198=== PAUSE TestValidateToken_NoMatchingProvider2199=== RUN TestValidateToken_KubernetesServiceAccount2200=== PAUSE TestValidateToken_KubernetesServiceAccount2201=== RUN TestNewValidator_KubernetesRequiresCA2202=== PAUSE TestNewValidator_KubernetesRequiresCA2203=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2204=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2205=== RUN TestPins_ReservedForMatchingRule2206=== PAUSE TestPins_ReservedForMatchingRule2207=== RUN TestPins_TopLevelShorthand2208=== PAUSE TestPins_TopLevelShorthand2209=== RUN TestPins_ConfigValidation2210=== PAUSE TestPins_ConfigValidation2211=== RUN TestScopes_LegacyProviderDefaultsToWrite2212=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2213=== RUN TestScopes_Rules2214=== PAUSE TestScopes_Rules2215=== RUN TestScopes_ConfigValidation2216=== PAUSE TestScopes_ConfigValidation2217=== CONT TestAudienceForIssuer2218--- PASS: TestAudienceForIssuer (0.00s)2219=== CONT TestPins_ConfigValidation2220=== CONT TestScopes_Rules2221=== CONT TestValidateToken_NoMatchingProvider2222=== CONT TestValidateToken_MultipleProviders2223=== CONT TestValidateToken_BoundSubjectMismatch2224=== CONT TestValidateToken_BoundClaimsMismatch2225=== CONT TestValidateToken_Expired2226--- PASS: TestPins_ConfigValidation (0.01s)2227=== CONT TestValidateToken_WrongAudience2228=== CONT TestValidateToken_ValidToken2229=== CONT TestGlobMatch2230=== RUN TestGlobMatch/foo_foo2231=== PAUSE TestGlobMatch/foo_foo2232=== RUN TestGlobMatch/foo_bar2233=== PAUSE TestGlobMatch/foo_bar2234=== CONT TestScopes_ConfigValidation2235=== CONT TestPins_ReservedForMatchingRule2236--- PASS: TestScopes_ConfigValidation (0.00s)2237=== CONT TestPins_TopLevelShorthand2238=== CONT TestScopes_LegacyProviderDefaultsToWrite2239=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2240=== CONT TestNewValidator_KubernetesRequiresCA2241=== CONT TestValidateToken_KubernetesServiceAccount2242=== RUN TestGlobMatch/*_2243=== PAUSE TestGlobMatch/*_2244=== RUN TestGlobMatch/*_anything2245=== PAUSE TestGlobMatch/*_anything2246=== RUN TestGlobMatch/foo*_foo2247=== PAUSE TestGlobMatch/foo*_foo2248=== RUN TestGlobMatch/foo*_foobar2249=== PAUSE TestGlobMatch/foo*_foobar2250=== RUN TestGlobMatch/foo*_bar2251=== PAUSE TestGlobMatch/foo*_bar2252=== RUN TestGlobMatch/*bar_bar2253=== PAUSE TestGlobMatch/*bar_bar2254=== RUN TestGlobMatch/*bar_foobar2255=== PAUSE TestGlobMatch/*bar_foobar2256=== RUN TestGlobMatch/*bar_foo2257=== PAUSE TestGlobMatch/*bar_foo2258=== RUN TestGlobMatch/foo*bar_foobar2259=== PAUSE TestGlobMatch/foo*bar_foobar2260=== RUN TestGlobMatch/foo*bar_foo123bar2261=== PAUSE TestGlobMatch/foo*bar_foo123bar2262=== RUN TestGlobMatch/foo*bar_foobarbaz2263=== PAUSE TestGlobMatch/foo*bar_foobarbaz2264=== RUN TestGlobMatch/*/*_foo/bar2265=== PAUSE TestGlobMatch/*/*_foo/bar2266=== RUN TestGlobMatch/*/*_foo2267=== PAUSE TestGlobMatch/*/*_foo2268=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2269=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2270=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02271=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02272=== RUN TestGlobMatch/refs/*/main_refs/heads/main2273=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2274=== RUN TestGlobMatch/fo?_foo2275=== PAUSE TestGlobMatch/fo?_foo2276=== RUN TestGlobMatch/fo?_fo2277=== PAUSE TestGlobMatch/fo?_fo2278=== RUN TestGlobMatch/fo?_fooo2279=== PAUSE TestGlobMatch/fo?_fooo2280=== RUN TestGlobMatch/?oo_foo2281=== PAUSE TestGlobMatch/?oo_foo2282=== RUN TestGlobMatch/?oo_boo2283=== PAUSE TestGlobMatch/?oo_boo2284=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2285=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2286=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2287=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2288=== CONT TestGlobMatch/foo_foo2289=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2290=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2291=== CONT TestGlobMatch/?oo_boo2292=== CONT TestGlobMatch/?oo_foo2293=== CONT TestGlobMatch/fo?_fooo2294=== CONT TestGlobMatch/fo?_fo2295=== CONT TestGlobMatch/fo?_foo2296=== CONT TestGlobMatch/refs/*/main_refs/heads/main2297=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02298=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2299=== CONT TestGlobMatch/*/*_foo2300=== CONT TestGlobMatch/*/*_foo/bar2301=== CONT TestGlobMatch/foo*bar_foobarbaz2302=== CONT TestGlobMatch/foo*bar_foo123bar2303=== CONT TestGlobMatch/foo*bar_foobar2304=== CONT TestGlobMatch/*bar_foo2305=== CONT TestGlobMatch/*bar_foobar2306=== CONT TestGlobMatch/*bar_bar2307=== CONT TestGlobMatch/foo*_bar2308=== CONT TestGlobMatch/foo*_foobar2309=== CONT TestGlobMatch/foo*_foo2310=== CONT TestGlobMatch/*_anything2311=== CONT TestGlobMatch/*_2312=== CONT TestGlobMatch/foo_bar2313--- PASS: TestGlobMatch (0.04s)2314 --- PASS: TestGlobMatch/foo_foo (0.00s)2315 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2316 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2317 --- PASS: TestGlobMatch/?oo_boo (0.00s)2318 --- PASS: TestGlobMatch/?oo_foo (0.00s)2319 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2320 --- PASS: TestGlobMatch/fo?_fo (0.00s)2321 --- PASS: TestGlobMatch/fo?_foo (0.00s)2322 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2323 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2324 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2325 --- PASS: TestGlobMatch/*/*_foo (0.00s)2326 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2327 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2328 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2329 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2330 --- PASS: TestGlobMatch/*bar_foo (0.00s)2331 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2332 --- PASS: TestGlobMatch/*bar_bar (0.00s)2333 --- PASS: TestGlobMatch/foo*_bar (0.00s)2334 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2335 --- PASS: TestGlobMatch/foo*_foo (0.00s)2336 --- PASS: TestGlobMatch/*_anything (0.00s)2337 --- PASS: TestGlobMatch/*_ (0.00s)2338 --- PASS: TestGlobMatch/foo_bar (0.00s)23392026/10/27 08:16:57 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12323402026/10/27 08:16:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63321/oidc23412026/10/27 08:16:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63324/oidc2342--- PASS: TestValidateToken_BoundSubjectMismatch (0.11s)23432026/10/27 08:16:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63329/oidc23442026/10/27 08:16:57 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:63320/oidc2345--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.10s)23462026/10/27 08:16:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63332/oidc23472026/10/27 08:16:57 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:63327/oidc2348--- PASS: TestValidateToken_WrongAudience (0.12s)2349--- PASS: TestPins_ReservedForMatchingRule (0.11s)2350--- PASS: TestValidateToken_ValidToken (0.12s)2351--- PASS: TestValidateToken_MultipleProviders (0.14s)23522026/10/27 08:16:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63335/oidc2353--- PASS: TestValidateToken_BoundClaimsMismatch (0.16s)23542026/10/27 08:16:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63337/oidc2355--- PASS: TestPins_TopLevelShorthand (0.14s)23562026/10/27 08:16:57 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:633392357--- PASS: TestValidateToken_KubernetesServiceAccount (0.13s)23582026/10/27 08:16:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63341/oidc2359--- PASS: TestScopes_Rules (0.18s)23602026/10/27 08:16:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63343/oidc23612026/10/27 08:16:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:63345/oidc2362--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.16s)2363--- PASS: TestValidateToken_Expired (0.18s)23642026/10/27 08:16:57 http: TLS handshake error from 127.0.0.1:63348: read tcp 127.0.0.1:63347->127.0.0.1:63348: use of closed network connection2365--- PASS: TestNewValidator_KubernetesRequiresCA (0.18s)23662026/10/27 08:16:57 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:63349/oidc2367--- PASS: TestValidateToken_NoMatchingProvider (0.32s)2368PASS2369Running hook tests...2370=== RUN TestSendPathsEmpty2371=== PAUSE TestSendPathsEmpty2372=== RUN TestQueueEnqueueAndFetch2373=== PAUSE TestQueueEnqueueAndFetch2374=== RUN TestQueueDeduplication2375=== PAUSE TestQueueDeduplication2376=== RUN TestQueueRemove2377=== PAUSE TestQueueRemove2378=== RUN TestQueueFetchBatchLimit2379=== PAUSE TestQueueFetchBatchLimit2380=== RUN TestQueueRetryMovesToBack2381=== PAUSE TestQueueRetryMovesToBack2382=== RUN TestQueueFetchRemoveLifecycle2383=== PAUSE TestQueueFetchRemoveLifecycle2384=== RUN TestQueueConcurrentWriters2385=== PAUSE TestQueueConcurrentWriters2386=== RUN TestQueueRemoveLargeClosure2387=== PAUSE TestQueueRemoveLargeClosure2388=== RUN TestServerClientIntegration2389--- PASS: TestServerClientIntegration (0.00s)2390=== RUN TestServerQueueError23912026/10/27 08:16:58 ERROR Failed to queue paths error="permission denied" count=12392--- PASS: TestServerQueueError (0.00s)2393=== RUN TestGetListenerSocketActivation2394 server_test.go:145: systemd socket activation does not exist on darwin2395--- SKIP: TestGetListenerSocketActivation (0.00s)2396=== RUN TestServerStalledClientDoesNotBlockShutdown2397=== PAUSE TestServerStalledClientDoesNotBlockShutdown2398=== RUN TestServerBacksOffOnAcceptErrors2399=== PAUSE TestServerBacksOffOnAcceptErrors2400=== RUN TestDrainIsolatesPoisonPath2401=== PAUSE TestDrainIsolatesPoisonPath2402=== RUN TestRunNotBlockedByPoisonHead2403=== PAUSE TestRunNotBlockedByPoisonHead2404=== RUN TestDrainGivesUpWhenServerDown2405=== PAUSE TestDrainGivesUpWhenServerDown2406=== RUN TestFailedPathPrunedByLaterClosure2407=== PAUSE TestFailedPathPrunedByLaterClosure2408=== RUN TestWorkerUploadsAndRemoves2409=== PAUSE TestWorkerUploadsAndRemoves2410=== RUN TestWorkerSkipsGCdPaths2411=== PAUSE TestWorkerSkipsGCdPaths2412=== RUN TestWorkerPrunesClosureDeps2413=== PAUSE TestWorkerPrunesClosureDeps2414=== RUN TestDrainTimeout2415=== PAUSE TestDrainTimeout2416=== RUN TestWorkerRemoveFailureIsNotProgress2417=== PAUSE TestWorkerRemoveFailureIsNotProgress2418=== RUN TestWorkerKeepsPathItCannotStat2419=== PAUSE TestWorkerKeepsPathItCannotStat2420=== CONT TestSendPathsEmpty2421=== CONT TestDrainIsolatesPoisonPath2422--- PASS: TestSendPathsEmpty (0.00s)2423=== CONT TestServerBacksOffOnAcceptErrors24242026/10/27 08:16:58 ERROR Accept failed error="too many open files"2425=== CONT TestServerStalledClientDoesNotBlockShutdown2426=== CONT TestQueueRemoveLargeClosure2427=== CONT TestQueueConcurrentWriters2428=== CONT TestQueueFetchRemoveLifecycle2429=== CONT TestQueueRetryMovesToBack2430=== CONT TestQueueFetchBatchLimit2431=== CONT TestQueueRemove2432=== CONT TestQueueDeduplication2433=== CONT TestQueueEnqueueAndFetch2434=== CONT TestWorkerSkipsGCdPaths2435=== CONT TestWorkerRemoveFailureIsNotProgress2436=== CONT TestDrainTimeout2437=== CONT TestWorkerKeepsPathItCannotStat2438=== CONT TestWorkerPrunesClosureDeps2439=== CONT TestFailedPathPrunedByLaterClosure2440=== CONT TestWorkerUploadsAndRemoves2441=== CONT TestDrainGivesUpWhenServerDown2442=== CONT TestRunNotBlockedByPoisonHead24432026/10/27 08:16:58 ERROR Accept failed error="too many open files"2444--- PASS: TestQueueFetchRemoveLifecycle (0.01s)24452026/10/27 08:16:58 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestWorkerKeepsPathItCannotStat1797709268/002/locked/aaa error="stat /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestWorkerKeepsPathItCannotStat1797709268/002/locked/aaa: permission denied"2446--- PASS: TestQueueRetryMovesToBack (0.01s)2447--- PASS: TestQueueEnqueueAndFetch (0.01s)24482026/10/27 08:16:58 INFO Uploading batch count=22449--- PASS: TestQueueRemove (0.01s)24502026/10/27 08:16:58 INFO Uploading batch count=124512026/10/27 08:16:58 ERROR Upload failed error="upload failed" count=124522026/10/27 08:16:58 INFO Uploading batch count=124532026/10/27 08:16:58 INFO Upload queue status pending=224542026/10/27 08:16:58 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestWorkerSkipsGCdPaths1307557888/002/nonexistent24552026/10/27 08:16:58 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestWorkerKeepsPathItCannotStat1797709268/002/locked/aaa error="stat /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestWorkerKeepsPathItCannotStat1797709268/002/locked/aaa: permission denied"24562026/10/27 08:16:58 INFO Uploading batch count=424572026/10/27 08:16:58 ERROR Upload failed error="upload failed" count=424582026/10/27 08:16:58 INFO Uploading batch count=124592026/10/27 08:16:58 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestDrainIsolatesPoisonPath2892620966/002/bbb24602026/10/27 08:16:58 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestWorkerKeepsPathItCannotStat1797709268/002/locked/aaa error="stat /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestWorkerKeepsPathItCannotStat1797709268/002/locked/aaa: permission denied"24612026/10/27 08:16:58 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestWorkerRemoveFailureIsNotProgress3554850131/002/nonexistent24622026/10/27 08:16:58 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124632026/10/27 08:16:58 ERROR Drain finished with paths left in queue remaining=124642026/10/27 08:16:58 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestWorkerRemoveFailureIsNotProgress3554850131/002/nonexistent24652026/10/27 08:16:58 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124662026/10/27 08:16:58 INFO Uploading batch count=124672026/10/27 08:16:58 ERROR Upload failed error="upload failed" count=124682026/10/27 08:16:58 INFO Uploading batch count=124692026/10/27 08:16:58 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestWorkerRemoveFailureIsNotProgress3554850131/002/nonexistent24702026/10/27 08:16:58 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=124712026/10/27 08:16:58 ERROR Drain finished with paths left in queue remaining=124722026/10/27 08:16:58 INFO Uploading batch count=124732026/10/27 08:16:58 ERROR Upload failed error="upload failed" count=124742026/10/27 08:16:58 INFO Uploading batch count=124752026/10/27 08:16:58 ERROR Upload failed error="upload failed" count=12476--- PASS: TestWorkerKeepsPathItCannotStat (0.01s)2477--- PASS: TestWorkerRemoveFailureIsNotProgress (0.01s)24782026/10/27 08:16:58 INFO Upload queue status pending=224792026/10/27 08:16:58 INFO Uploading batch count=12480--- PASS: TestQueueFetchBatchLimit (0.01s)2481--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)24822026/10/27 08:16:58 ERROR Accept failed error="too many open files"24832026/10/27 08:16:58 INFO Upload queue status pending=22484--- PASS: TestQueueDeduplication (0.01s)24852026/10/27 08:16:58 INFO Uploading batch count=224862026/10/27 08:16:58 ERROR Drain finished with paths left in queue remaining=124872026/10/27 08:16:58 INFO Upload queue status pending=324882026/10/27 08:16:58 INFO Uploading batch count=124892026/10/27 08:16:58 ERROR Upload failed error="upload failed" count=124902026/10/27 08:16:58 INFO Uploading batch count=224912026/10/27 08:16:58 ERROR Upload failed error="upload failed" count=224922026/10/27 08:16:58 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestDrainGivesUpWhenServerDown1695812035/002/a24932026/10/27 08:16:58 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestDrainGivesUpWhenServerDown1695812035/002/b2494--- PASS: TestDrainIsolatesPoisonPath (0.02s)24952026/10/27 08:16:58 INFO Uploading batch count=224962026/10/27 08:16:58 ERROR Upload failed error="upload failed" count=224972026/10/27 08:16:58 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestDrainGivesUpWhenServerDown1695812035/002/c24982026/10/27 08:16:58 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestDrainGivesUpWhenServerDown1695812035/002/d24992026/10/27 08:16:58 INFO Uploading batch count=225002026/10/27 08:16:58 ERROR Upload failed error="upload failed" count=225012026/10/27 08:16:58 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestDrainGivesUpWhenServerDown1695812035/002/e25022026/10/27 08:16:58 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestDrainGivesUpWhenServerDown1695812035/002/f25032026/10/27 08:16:58 ERROR Drain finished with paths left in queue remaining=102504--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2505--- PASS: TestWorkerPrunesClosureDeps (0.03s)2506--- PASS: TestWorkerSkipsGCdPaths (0.03s)25072026/10/27 08:16:58 ERROR Accept failed error="too many open files"2508--- PASS: TestWorkerUploadsAndRemoves (0.03s)2509--- PASS: TestQueueRemoveLargeClosure (0.04s)25102026/10/27 08:16:58 ERROR Accept failed error="too many open files"2511--- PASS: TestQueueConcurrentWriters (0.13s)25122026/10/27 08:16:58 ERROR Accept failed error="too many open files"25132026/10/27 08:16:58 ERROR Failed to decode request error="read unix /private/var/tb/4/scratch/31ac9e0308c9e79b/build/hook1990582772/test.sock->: i/o timeout"25142026/10/27 08:16:58 ERROR Failed to write response error="write unix /private/var/tb/4/scratch/31ac9e0308c9e79b/build/hook1990582772/test.sock->: i/o timeout"2515--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)25162026/10/27 08:16:58 ERROR Upload failed error="context deadline exceeded" count=225172026/10/27 08:16:58 ERROR Drain finished with paths left in queue remaining=42518--- PASS: TestDrainTimeout (0.21s)25192026/10/27 08:16:58 ERROR Accept failed error="too many open files"25202026/10/27 08:16:58 ERROR Accept failed error="too many open files"2521--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)25222026/10/27 08:16:59 INFO Uploading batch count=125232026/10/27 08:16:59 INFO Uploading batch count=125242026/10/27 08:16:59 INFO Uploading batch count=125252026/10/27 08:16:59 ERROR Upload failed error="upload failed" count=125262026/10/27 08:16:59 INFO Uploading batch count=125272026/10/27 08:16:59 ERROR Upload failed error="upload failed" count=125282026/10/27 08:16:59 INFO Uploading batch count=125292026/10/27 08:16:59 ERROR Upload failed error="upload failed" count=125302026/10/27 08:16:59 INFO Uploading batch count=125312026/10/27 08:16:59 ERROR Upload failed error="upload failed" count=125322026/10/27 08:16:59 ERROR Drain finished with paths left in queue remaining=12533--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2534PASS2535Running signing tests...2536=== RUN TestExternalSigner2537=== PAUSE TestExternalSigner2538=== RUN TestExternalSignerWrongPublicKey2539=== PAUSE TestExternalSignerWrongPublicKey2540=== RUN TestExternalSignerErrors2541=== PAUSE TestExternalSignerErrors2542=== RUN TestExternalSignerRestartsAfterCrash2543=== PAUSE TestExternalSignerRestartsAfterCrash2544=== RUN TestExternalSignerProgramErrorKeepsProcess2545=== PAUSE TestExternalSignerProgramErrorKeepsProcess2546=== RUN TestExternalSignerClose2547=== PAUSE TestExternalSignerClose2548=== RUN TestExternalSignerRejectsInvalidPublicKey2549=== PAUSE TestExternalSignerRejectsInvalidPublicKey2550=== RUN TestExternalSignerCancellation2551=== PAUSE TestExternalSignerCancellation2552=== RUN TestGenerateFingerprint2553=== PAUSE TestGenerateFingerprint2554=== RUN TestParseSigningKey2555=== PAUSE TestParseSigningKey2556=== RUN TestSign2557=== PAUSE TestSign2558=== RUN TestSignBatch2559=== PAUSE TestSignBatch2560=== RUN TestNilKeyPublicKey2561=== PAUSE TestNilKeyPublicKey2562=== RUN TestSignErrors2563=== PAUSE TestSignErrors2564=== CONT TestExternalSigner2565=== CONT TestSignBatch2566=== CONT TestExternalSignerClose2567=== CONT TestExternalSignerProgramErrorKeepsProcess2568=== CONT TestNilKeyPublicKey2569--- PASS: TestNilKeyPublicKey (0.00s)2570=== CONT TestExternalSignerCancellation2571=== CONT TestSign2572=== CONT TestParseSigningKey2573=== RUN TestParseSigningKey/valid_32-byte_key2574=== CONT TestGenerateFingerprint2575=== RUN TestGenerateFingerprint/basic_with_references2576=== CONT TestExternalSignerErrors2577=== RUN TestExternalSignerErrors/null2578=== PAUSE TestExternalSignerErrors/null2579=== RUN TestExternalSignerErrors/missing_signatures2580=== PAUSE TestExternalSignerErrors/missing_signatures2581=== RUN TestExternalSignerErrors/missing_signature_name2582=== PAUSE TestExternalSignerErrors/missing_signature_name2583=== CONT TestExternalSignerRestartsAfterCrash2584=== CONT TestExternalSignerRejectsInvalidPublicKey2585=== RUN TestExternalSignerRejectsInvalidPublicKey/#002586=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002587=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2588=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2589=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2590=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2591=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2592=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2593=== CONT TestExternalSignerWrongPublicKey2594=== CONT TestSignErrors2595=== PAUSE TestParseSigningKey/valid_32-byte_key2596=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2597=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2598=== RUN TestParseSigningKey/no_colon2599=== PAUSE TestParseSigningKey/no_colon2600=== RUN TestParseSigningKey/empty_name2601=== PAUSE TestParseSigningKey/empty_name2602=== RUN TestParseSigningKey/invalid_base642603=== PAUSE TestParseSigningKey/invalid_base642604=== RUN TestParseSigningKey/wrong_length2605=== PAUSE TestParseSigningKey/wrong_length2606=== CONT TestParseSigningKey/valid_32-byte_key2607=== PAUSE TestGenerateFingerprint/basic_with_references2608=== RUN TestGenerateFingerprint/no_references2609=== PAUSE TestGenerateFingerprint/no_references2610=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2611=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2612=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2613=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2614=== RUN TestGenerateFingerprint/invalid_nar_hash_length2615=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2616=== RUN TestGenerateFingerprint/invalid_store_path_prefix2617=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2618=== RUN TestGenerateFingerprint/invalid_reference_prefix2619=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2620=== CONT TestGenerateFingerprint/basic_with_references2621=== CONT TestParseSigningKey/empty_name2622=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2623=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2624=== CONT TestExternalSignerRejectsInvalidPublicKey/#002625=== CONT TestGenerateFingerprint/invalid_reference_prefix2626=== CONT TestGenerateFingerprint/invalid_store_path_prefix2627=== CONT TestGenerateFingerprint/invalid_nar_hash_length2628=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2629=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2630=== CONT TestGenerateFingerprint/no_references2631--- PASS: TestGenerateFingerprint (0.00s)2632 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2633 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2634 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2635 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2636 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2637 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2638 --- PASS: TestGenerateFingerprint/no_references (0.00s)2639=== CONT TestParseSigningKey/wrong_length2640=== CONT TestParseSigningKey/invalid_base642641=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2642=== CONT TestParseSigningKey/no_colon2643=== RUN TestExternalSignerErrors/invalid_signature_base642644=== PAUSE TestExternalSignerErrors/invalid_signature_base642645=== RUN TestExternalSignerErrors/exit_at_startup2646=== PAUSE TestExternalSignerErrors/exit_at_startup2647=== RUN TestExternalSignerErrors/exit_on_request2648=== PAUSE TestExternalSignerErrors/exit_on_request2649=== RUN TestExternalSignerErrors/null_signatures2650=== PAUSE TestExternalSignerErrors/null_signatures2651=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2652=== RUN TestExternalSignerErrors/wrong_id2653=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2654=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2655=== PAUSE TestExternalSignerErrors/wrong_id2656=== RUN TestExternalSignerErrors/too_few_signatures2657=== PAUSE TestExternalSignerErrors/too_few_signatures2658=== RUN TestExternalSignerErrors/unrequested_key2659=== PAUSE TestExternalSignerErrors/unrequested_key2660=== RUN TestExternalSignerErrors/program_error2661=== PAUSE TestExternalSignerErrors/program_error2662=== RUN TestExternalSignerErrors/invalid_JSON2663=== PAUSE TestExternalSignerErrors/invalid_JSON2664=== RUN TestExternalSignerErrors/wrong_shape2665=== PAUSE TestExternalSignerErrors/wrong_shape2666--- PASS: TestSign (0.00s)2667=== RUN TestExternalSignerErrors/wrong_signatures_shape2668=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2669=== RUN TestExternalSignerErrors/wrong_signature_name2670=== PAUSE TestExternalSignerErrors/wrong_signature_name2671=== RUN TestExternalSignerErrors/wrong_signature_length2672=== PAUSE TestExternalSignerErrors/wrong_signature_length2673=== CONT TestExternalSignerErrors/null2674--- PASS: TestParseSigningKey (0.00s)2675 --- PASS: TestParseSigningKey/empty_name (0.00s)2676 --- PASS: TestParseSigningKey/wrong_length (0.00s)2677 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2678 --- PASS: TestParseSigningKey/no_colon (0.00s)2679 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2680 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2681=== CONT TestExternalSignerErrors/unrequested_key2682=== RUN TestSignErrors/nil_key2683=== CONT TestExternalSignerErrors/invalid_JSON2684=== CONT TestExternalSignerErrors/missing_signature_name2685--- PASS: TestSignBatch (0.00s)2686=== CONT TestExternalSignerErrors/invalid_signature_base642687=== CONT TestExternalSignerErrors/wrong_shape2688=== CONT TestExternalSignerErrors/wrong_signature_length2689=== CONT TestExternalSignerErrors/missing_signatures2690=== CONT TestExternalSignerErrors/wrong_signature_name2691=== CONT TestExternalSignerErrors/program_error2692=== CONT TestExternalSignerErrors/exit_at_startup2693=== CONT TestExternalSignerErrors/too_few_signatures2694=== CONT TestExternalSignerErrors/wrong_id2695=== CONT TestExternalSignerErrors/null_signatures2696=== CONT TestExternalSignerErrors/exit_on_request2697=== PAUSE TestSignErrors/nil_key2698=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2699=== CONT TestExternalSignerErrors/wrong_signatures_shape2700=== RUN TestSignErrors/nil_narinfo2701=== PAUSE TestSignErrors/nil_narinfo2702=== RUN TestSignErrors/invalid_narinfo2703=== PAUSE TestSignErrors/invalid_narinfo2704=== RUN TestSignErrors/canceled2705--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2706 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2707 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2708 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2709 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2710 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2711=== PAUSE TestSignErrors/canceled2712=== CONT TestSignErrors/nil_key2713=== CONT TestSignErrors/invalid_narinfo2714=== CONT TestSignErrors/nil_narinfo2715=== CONT TestSignErrors/canceled2716--- PASS: TestSignErrors (0.00s)2717 --- PASS: TestSignErrors/nil_key (0.00s)2718 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2719 --- PASS: TestSignErrors/nil_narinfo (0.00s)2720 --- PASS: TestSignErrors/canceled (0.00s)2721--- PASS: TestExternalSigner (0.21s)2722--- PASS: TestExternalSignerCancellation (0.39s)2723--- PASS: TestExternalSignerProgramErrorKeepsProcess (1.84s)2724--- PASS: TestExternalSignerWrongPublicKey (2.21s)2725--- PASS: TestExternalSignerClose (2.78s)2726--- PASS: TestExternalSignerRestartsAfterCrash (3.35s)2727/private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestExternalSignerRestartsAfterCrash2523999005/001/sign program: line 7: /private/var/tb/4/scratch/31ac9e0308c9e79b/build/TestExternalSignerRestartsAfterCrash2523999005/001/sign program.starts: No such file or directory2728--- PASS: TestExternalSignerErrors (0.00s)2729 --- PASS: TestExternalSignerErrors/too_few_signatures (0.56s)2730 --- PASS: TestExternalSignerErrors/null_signatures (1.29s)2731 --- PASS: TestExternalSignerErrors/missing_signatures (1.47s)2732 --- PASS: TestExternalSignerErrors/missing_signature_name (1.66s)2733 --- PASS: TestExternalSignerErrors/invalid_JSON (2.02s)2734 --- PASS: TestExternalSignerErrors/exit_at_startup (2.39s)2735 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (2.57s)2736 --- PASS: TestExternalSignerErrors/wrong_id (2.96s)2737 --- PASS: TestExternalSignerErrors/null (3.15s)2738 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (3.51s)2739 --- PASS: TestExternalSignerErrors/wrong_signature_name (3.70s)2740 --- PASS: TestExternalSignerErrors/wrong_shape (3.88s)2741 --- PASS: TestExternalSignerErrors/unrequested_key (4.07s)2742 --- PASS: TestExternalSignerErrors/wrong_signature_length (4.26s)2743 --- PASS: TestExternalSignerErrors/program_error (4.45s)2744 --- PASS: TestExternalSignerErrors/exit_on_request (4.63s)2745PASS2746Running OpenBao signer tests...2747=== RUN TestSign2748=== PAUSE TestSign2749=== RUN TestSignErrors2750=== PAUSE TestSignErrors2751=== RUN TestServe2752=== PAUSE TestServe2753=== RUN TestServeRejectsGarbage2754=== PAUSE TestServeRejectsGarbage2755=== CONT TestSign2756=== CONT TestServe2757=== CONT TestServeRejectsGarbage2758--- PASS: TestServeRejectsGarbage (0.00s)2759=== CONT TestSignErrors2760=== RUN TestSignErrors/http_error2761=== PAUSE TestSignErrors/http_error2762=== RUN TestSignErrors/invalid_json2763=== PAUSE TestSignErrors/invalid_json2764=== RUN TestSignErrors/no_prefix2765=== PAUSE TestSignErrors/no_prefix2766=== RUN TestSignErrors/invalid_base642767=== PAUSE TestSignErrors/invalid_base642768=== CONT TestSignErrors/http_error2769=== CONT TestSignErrors/no_prefix2770--- PASS: TestServe (0.00s)2771=== CONT TestSignErrors/invalid_json2772=== CONT TestSignErrors/invalid_base642773--- PASS: TestSign (0.00s)2774--- PASS: TestSignErrors (0.00s)2775 --- PASS: TestSignErrors/http_error (0.00s)2776 --- PASS: TestSignErrors/invalid_base64 (0.00s)2777 --- PASS: TestSignErrors/invalid_json (0.00s)2778 --- PASS: TestSignErrors/no_prefix (0.00s)2779PASS