niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #463
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_ReturnsAfterDroppedBody20=== PAUSE TestUploadMultipart_ReturnsAfterDroppedBody21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.10s)27=== RUN TestDumpPathCaseHackCollision28--- PASS: TestDumpPathCaseHackCollision (0.00s)29=== RUN TestSupersededNARStillUploadsListing30=== PAUSE TestSupersededNARStillUploadsListing31=== RUN TestDumpPathMatchesNix32=== PAUSE TestDumpPathMatchesNix33=== RUN TestDumpPathSingleFile34=== PAUSE TestDumpPathSingleFile35=== RUN TestDumpPathWriterError36=== PAUSE TestDumpPathWriterError37=== RUN TestEncodeNixBase3238=== PAUSE TestEncodeNixBase3239=== RUN TestEncodeNixBase32WithRealHash40=== PAUSE TestEncodeNixBase32WithRealHash41=== RUN TestConvertHashToNix3242=== PAUSE TestConvertHashToNix3243=== RUN TestGetStorePathHash44=== PAUSE TestGetStorePathHash45=== RUN TestPathInfoHashCompatibility46=== PAUSE TestPathInfoHashCompatibility47=== RUN TestParsePathInfoJSON48=== PAUSE TestParsePathInfoJSON49=== RUN TestParsePathInfoJSONMultiplePaths50=== PAUSE TestParsePathInfoJSONMultiplePaths51=== RUN TestPathInfoCACompatibility52=== PAUSE TestPathInfoCACompatibility53=== RUN TestRateLimiterFeedback54=== PAUSE TestRateLimiterFeedback55=== RUN TestRateLimiterFeedback_400DoesNotCountAsSuccess56=== PAUSE TestRateLimiterFeedback_400DoesNotCountAsSuccess57=== RUN TestRegisterUploadedObject_BoundedAgainstSilentServer58=== PAUSE TestRegisterUploadedObject_BoundedAgainstSilentServer59=== RUN TestResolveStorePath60=== PAUSE TestResolveStorePath61=== RUN TestDoWithRetry_BodyReplayedViaGetBody62=== PAUSE TestDoWithRetry_BodyReplayedViaGetBody63=== RUN TestRetryTimeoutOutlastsMaxRetries64=== PAUSE TestRetryTimeoutOutlastsMaxRetries65=== RUN TestDoWithRetry_FinalResponseBodyReadable66=== PAUSE TestDoWithRetry_FinalResponseBodyReadable67=== RUN TestShellSplit68=== PAUSE TestShellSplit69=== RUN TestShellSplitErrors70=== PAUSE TestShellSplitErrors71=== RUN TestStreamPushReportsEveryPath72=== PAUSE TestStreamPushReportsEveryPath73=== RUN TestStreamPushBatchesUnderLoad74=== PAUSE TestStreamPushBatchesUnderLoad75=== RUN TestStreamPushIsolatesFailures76=== PAUSE TestStreamPushIsolatesFailures77=== RUN TestStreamPushGivesUpOnDeadServer78=== PAUSE TestStreamPushGivesUpOnDeadServer79=== RUN TestStreamPushRequestLine80=== PAUSE TestStreamPushRequestLine81=== RUN TestStreamPushReportsSignatures82=== PAUSE TestStreamPushReportsSignatures83=== RUN TestStreamPushReportsSkippedPaths84=== PAUSE TestStreamPushReportsSkippedPaths85=== RUN TestClientSignaturesByStorePath86=== PAUSE TestClientSignaturesByStorePath87=== RUN TestStreamPushStopsWhenCanceled88=== PAUSE TestStreamPushStopsWhenCanceled89=== RUN TestSetClientTLS90=== PAUSE TestSetClientTLS91=== RUN TestSetClientTLSDoesNotMutateDefaultTransport92=== PAUSE TestSetClientTLSDoesNotMutateDefaultTransport93=== RUN TestSetClientTLSErrors94=== PAUSE TestSetClientTLSErrors95=== RUN TestStaticToken96=== PAUSE TestStaticToken97=== RUN TestFileTokenReadsAndCaches98=== PAUSE TestFileTokenReadsAndCaches99=== RUN TestFileTokenMissing100=== PAUSE TestFileTokenMissing101=== RUN TestFileTokenEmpty102=== PAUSE TestFileTokenEmpty103=== RUN TestScriptTokenNoExpiryRerunsEveryCall104=== PAUSE TestScriptTokenNoExpiryRerunsEveryCall105=== RUN TestScriptTokenCachesUntilRefresh106=== PAUSE TestScriptTokenCachesUntilRefresh107=== RUN TestScriptTokenEmptyToken108=== PAUSE TestScriptTokenEmptyToken109=== RUN TestScriptTokenBadJSON110=== PAUSE TestScriptTokenBadJSON111=== RUN TestScriptTokenScriptFails112=== PAUSE TestScriptTokenScriptFails113=== RUN TestScriptTokenEmptyCommand114=== PAUSE TestScriptTokenEmptyCommand115=== CONT TestDoServerRequestAttachesToken116=== CONT TestDoWithRetry_BodyReplayedViaGetBody117=== CONT TestDumpPathWriterError118=== CONT TestUploadMultipart_PartsInParallel119=== CONT TestDumpPathSingleFile120=== CONT TestDumpPathMatchesNix121=== CONT TestSupersededNARStillUploadsListing122=== RUN TestSupersededNARStillUploadsListing/small_NAR123=== PAUSE TestSupersededNARStillUploadsListing/small_NAR124=== CONT TestUploadMultipart_SupersededByPeer125=== RUN TestUploadMultipart_SupersededByPeer/exists126=== CONT TestPartSizeForNAR127=== RUN TestSupersededNARStillUploadsListing/dump_cut_short128=== CONT TestUploadMultipart_ReturnsAfterDroppedBody129=== CONT TestFilterOversizedClosures130=== RUN TestFilterOversizedClosures/no_limit_keeps_everything131=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything132=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped133=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped134=== RUN TestFilterOversizedClosures/all_closures_skipped135=== PAUSE TestFilterOversizedClosures/all_closures_skipped136=== CONT TestParsePathInfoJSONMultiplePaths137=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths138=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths139=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths140=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths141=== CONT TestScriptTokenCachesUntilRefresh142=== CONT TestResolveStorePath143=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer144=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess145=== CONT TestRateLimiterFeedback146=== RUN TestRateLimiterFeedback/429_enables_limiter147=== CONT TestPathInfoCACompatibility148=== PAUSE TestRateLimiterFeedback/429_enables_limiter149=== RUN TestRateLimiterFeedback/503_enables_limiter150=== PAUSE TestRateLimiterFeedback/503_enables_limiter151=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter152=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter153=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter154=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter155=== RUN TestPathInfoCACompatibility/null_ca_field156=== PAUSE TestPathInfoCACompatibility/null_ca_field1572026/11/06 07:10:15 WARN Rate limiter enabled after throttle name=server-test rate=5158=== RUN TestPathInfoCACompatibility/old_string_format_-_text159=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text160=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive161=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive162=== RUN TestPathInfoCACompatibility/new_structured_format_-_text163=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text164=== CONT TestFileTokenMissing165=== CONT TestFileTokenEmpty166=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method167=== CONT TestSetClientTLS168=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method169=== CONT TestFileTokenReadsAndCaches170=== CONT TestStaticToken171=== CONT TestSetClientTLSErrors172=== CONT TestScriptTokenEmptyCommand173=== CONT TestSetClientTLSDoesNotMutateDefaultTransport174=== CONT TestScriptTokenScriptFails175=== CONT TestScriptTokenBadJSON176=== CONT TestStreamPushIsolatesFailures177=== CONT TestScriptTokenEmptyToken178=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short179=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails180=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails181=== PAUSE TestUploadMultipart_SupersededByPeer/exists182=== RUN TestUploadMultipart_SupersededByPeer/missing183=== PAUSE TestUploadMultipart_SupersededByPeer/missing184=== RUN TestPartSizeForNAR/zero_stays_at_minimum185=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum186=== RUN TestPartSizeForNAR/small_stays_at_minimum187=== PAUSE TestPartSizeForNAR/small_stays_at_minimum188=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum189=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum190=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts191=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts192=== RUN TestPartSizeForNAR/1_TiB193=== PAUSE TestPartSizeForNAR/1_TiB194=== RUN TestPartSizeForNAR/5_TiB_S3_max_object195=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object196=== RUN TestPartSizeForNAR/capped_at_5_GiB197=== PAUSE TestPartSizeForNAR/capped_at_5_GiB198=== CONT TestClientSignaturesByStorePath199=== CONT TestStreamPushReportsSignatures200=== CONT TestScriptTokenNoExpiryRerunsEveryCall201=== CONT TestStreamPushReportsSkippedPaths2022026/11/06 07:10:15 ERROR Upload failed error="bad path" count=3203--- PASS: TestResolveStorePath (0.00s)204--- PASS: TestFileTokenMissing (0.00s)205--- PASS: TestStaticToken (0.00s)206--- PASS: TestScriptTokenEmptyCommand (0.00s)207--- PASS: TestFileTokenEmpty (0.00s)208--- PASS: TestClientSignaturesByStorePath (0.00s)209=== CONT TestRegisterUploadedObjectReusesConnections210=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica211=== CONT TestStreamPushStopsWhenCanceled212--- PASS: TestStreamPushStopsWhenCanceled (0.00s)213=== CONT TestStreamPushRequestLine214--- PASS: TestStreamPushReportsSkippedPaths (0.00s)215=== CONT TestStreamPushGivesUpOnDeadServer216--- PASS: TestStreamPushIsolatesFailures (0.00s)217=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry2182026/11/06 07:10:15 WARN Rate limiter enabled after throttle name=server-test rate=52192026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:534992202026/11/06 07:10:15 ERROR Upload failed error="connection refused" count=202212026/11/06 07:10:15 ERROR Server seems unavailable, giving up on batch untried=17222--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)223=== CONT TestCaseHackSuffix2242026/11/06 07:10:15 ERROR Upload failed error=boom count=12252026/11/06 07:10:15 ERROR Upload failed error=boom count=1226--- PASS: TestStreamPushReportsSignatures (0.00s)227=== CONT TestShellSplitErrors228--- PASS: TestShellSplitErrors (0.00s)229=== CONT TestStreamPushBatchesUnderLoad230=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false231=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false232=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true233=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true234=== CONT TestStreamPushReportsEveryPath235--- PASS: TestStreamPushReportsEveryPath (0.00s)236=== CONT TestGetStorePathHash237=== RUN TestGetStorePathHash/valid_store_path238=== PAUSE TestGetStorePathHash/valid_store_path239=== RUN TestGetStorePathHash/basename_without_hyphen_should_error240=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error241=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error242=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error243=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error244=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error245=== CONT TestParsePathInfoJSON246=== RUN TestParsePathInfoJSON/Nix_format247=== PAUSE TestParsePathInfoJSON/Nix_format248=== RUN TestParsePathInfoJSON/Lix_format249=== PAUSE TestParsePathInfoJSON/Lix_format250=== RUN TestParsePathInfoJSON/empty_input251=== PAUSE TestParsePathInfoJSON/empty_input252=== RUN TestParsePathInfoJSON/whitespace_only253=== PAUSE TestParsePathInfoJSON/whitespace_only254=== RUN TestParsePathInfoJSON/invalid_JSON255=== PAUSE TestParsePathInfoJSON/invalid_JSON256=== CONT TestPathInfoHashCompatibility257=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)258=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)259=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon260=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon261=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI262=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI263=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512264=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512265=== CONT TestDoWithRetry_FinalResponseBodyReadable266--- PASS: TestUploadMultipart_ReturnsAfterDroppedBody (0.02s)267=== CONT TestShellSplit268--- PASS: TestShellSplit (0.00s)269=== CONT TestRetryTimeoutOutlastsMaxRetries270--- PASS: TestDoServerRequestAttachesToken (0.02s)2712026/11/06 07:10:15 WARN Rate limiter backed off name=server-test rate=52722026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:53499273=== CONT TestEncodeNixBase32WithRealHash274--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)275=== CONT TestConvertHashToNix32276=== RUN TestConvertHashToNix32/SRI_format_to_Nix32277=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32278=== RUN TestConvertHashToNix32/already_Nix32_format279=== PAUSE TestConvertHashToNix32/already_Nix32_format280=== RUN TestConvertHashToNix32/invalid_format281=== PAUSE TestConvertHashToNix32/invalid_format282=== CONT TestEncodeNixBase32283=== RUN TestEncodeNixBase32/test_string_hash284=== PAUSE TestEncodeNixBase32/test_string_hash285=== RUN TestEncodeNixBase32/empty_input286=== PAUSE TestEncodeNixBase32/empty_input287=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun288--- PASS: TestFileTokenReadsAndCaches (0.01s)289=== CONT TestFilterOversizedClosures/no_limit_keeps_everything290=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths291=== CONT TestFilterOversizedClosures/all_closures_skipped2922026/11/06 07:10:15 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=50293=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2942026/11/06 07:10:15 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=2000295--- PASS: TestFilterOversizedClosures (0.00s)296 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)297 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)298 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)299=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths300--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)301 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)302 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)303=== CONT TestRateLimiterFeedback/429_enables_limiter304=== RUN TestSetClientTLSErrors/missing_cert_file305=== RUN TestSetClientTLS/rejects_connection_without_client_cert306=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert307=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA308=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA309=== RUN TestSetClientTLS/preserves_debug_logging_transport310=== PAUSE TestSetClientTLS/preserves_debug_logging_transport311=== CONT TestRateLimiterFeedback/503_enables_limiter3122026/11/06 07:10:15 WARN Rate limiter enabled after throttle name=server-test rate=53132026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:535103142026/11/06 07:10:15 INFO Garbage collection started315--- PASS: TestEncodeNixBase32WithRealHash (0.00s)316=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3172026/11/06 07:10:15 WARN Rate limiter backed off name=server-test rate=5318=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter319=== PAUSE TestSetClientTLSErrors/missing_cert_file320=== RUN TestSetClientTLSErrors/missing_key_file321=== PAUSE TestSetClientTLSErrors/missing_key_file322=== RUN TestSetClientTLSErrors/missing_ca_file323=== PAUSE TestSetClientTLSErrors/missing_ca_file324=== RUN TestSetClientTLSErrors/invalid_ca_file325=== PAUSE TestSetClientTLSErrors/invalid_ca_file326=== CONT TestPathInfoCACompatibility/null_ca_field327=== CONT TestPathInfoCACompatibility/new_structured_format_-_text328=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method329=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive330=== CONT TestPathInfoCACompatibility/old_string_format_-_text331--- PASS: TestPathInfoCACompatibility (0.00s)332 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)333 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)334 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)335 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)336 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)337=== CONT TestSupersededNARStillUploadsListing/small_NAR3382026/11/06 07:10:15 INFO Uploading abc-hello (1.0GB)339--- PASS: TestStreamPushRequestLine (0.02s)340=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails3412026/11/06 07:10:15 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=03422026/11/06 07:10:15 WARN Rate limiter enabled after throttle name=s3-test rate=53432026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:53517344--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.02s)345=== CONT TestSupersededNARStillUploadsListing/dump_cut_short3462026/11/06 07:10:15 WARN Garbage collection finished on another replica. Its statistics are not available here347--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)348=== CONT TestUploadMultipart_SupersededByPeer/exists349--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s)350=== CONT TestPartSizeForNAR/zero_stays_at_minimum351=== CONT TestUploadMultipart_SupersededByPeer/missing3522026/11/06 07:10:15 INFO Uploading abc-hello (1.0GB)353--- PASS: TestScriptTokenScriptFails (0.03s)354=== CONT TestPartSizeForNAR/1_TiB355=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts356=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum357=== CONT TestPartSizeForNAR/small_stays_at_minimum358=== CONT TestPartSizeForNAR/capped_at_5_GiB359=== CONT TestPartSizeForNAR/5_TiB_S3_max_object360--- PASS: TestPartSizeForNAR (0.01s)361 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)362 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)363 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)364 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)365 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)366 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)367 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)368=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false3692026/11/06 07:10:15 WARN Rate limiter enabled after throttle name=server-test rate=53702026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:535183712026/11/06 07:10:15 WARN Rate limiter enabled after throttle name=server-test rate=53722026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:535403732026/11/06 07:10:15 INFO Garbage collection started3742026/11/06 07:10:15 WARN Rate limiter backed off name=server-test rate=53752026/11/06 07:10:15 WARN Rate limiter backed off name=server-test rate=5376--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.04s)377=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true378=== CONT TestGetStorePathHash/valid_store_path379=== CONT TestParsePathInfoJSON/Nix_format380=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error381=== CONT TestGetStorePathHash/basename_without_hyphen_should_error382=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error383--- PASS: TestGetStorePathHash (0.00s)384 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)385 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)386 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)387 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)388=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)389=== CONT TestParsePathInfoJSON/invalid_JSON390=== CONT TestParsePathInfoJSON/empty_input391=== CONT TestParsePathInfoJSON/Lix_format392=== CONT TestParsePathInfoJSON/whitespace_only393--- PASS: TestParsePathInfoJSON (0.00s)394 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)395 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)396 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)397 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)398 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)399=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512400=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon401=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI402--- PASS: TestPathInfoHashCompatibility (0.00s)403 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)404 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)405 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)406 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)407=== CONT TestConvertHashToNix32/SRI_format_to_Nix32408=== CONT TestEncodeNixBase32/test_string_hash409=== CONT TestConvertHashToNix32/invalid_format410=== CONT TestEncodeNixBase32/empty_input411--- PASS: TestEncodeNixBase32 (0.00s)412 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)413 --- PASS: TestEncodeNixBase32/empty_input (0.00s)414=== CONT TestConvertHashToNix32/already_Nix32_format415--- PASS: TestConvertHashToNix32 (0.00s)416 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)417 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)418 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)419=== CONT TestSetClientTLS/rejects_connection_without_client_cert420=== CONT TestSetClientTLS/preserves_debug_logging_transport421--- PASS: TestStreamPushBatchesUnderLoad (0.00s)422 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)423 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)424=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA425--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.04s)426=== CONT TestSetClientTLSErrors/missing_cert_file427=== CONT TestSetClientTLSErrors/missing_ca_file428=== CONT TestSetClientTLSErrors/missing_key_file429=== CONT TestSetClientTLSErrors/invalid_ca_file430--- PASS: TestRateLimiterFeedback (0.00s)431 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)432 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.02s)433 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.03s)434 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.03s)4352026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:53516436--- PASS: TestSetClientTLSErrors (0.02s)437 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)438 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)439 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)440 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)4412026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:53516442--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)443 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.02s)444 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.02s)4452026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:535164462026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:53516447--- PASS: TestScriptTokenBadJSON (0.06s)4482026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:535164492026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:535164502026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:535164512026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:535164522026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:535164532026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:535164542026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:53516455--- PASS: TestScriptTokenEmptyToken (0.07s)4562026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:53516457--- PASS: TestRegisterUploadedObjectReusesConnections (0.07s)4582026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:535164592026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:535164602026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:535164612026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:535164622026/11/06 07:10:15 http: TLS handshake error from 127.0.0.1:53609: remote error: tls: bad certificate463--- PASS: TestSetClientTLS (0.02s)464 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)465 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)466 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.04s)4672026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:535164682026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:535164692026/11/06 07:10:15 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:53516470--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.10s)471--- PASS: TestScriptTokenCachesUntilRefresh (0.12s)4722026/11/06 07:10:15 INFO Uploading abc-hello (1.0GB)473--- PASS: TestCaseHackSuffix (0.13s)474--- PASS: TestDumpPathSingleFile (0.15s)475--- PASS: TestDumpPathWriterError (0.16s)4762026/11/06 07:10:15 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:53592/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:53592/part/24772026/11/06 07:10:15 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:53592/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:53592/part/34782026/11/06 07:10:15 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:53592/part/4\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:53592/part/4479--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.25s)4802026/11/06 07:10:15 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"481--- PASS: TestDumpPathMatchesNix (0.35s)482--- PASS: TestUploadMultipart_PartsInParallel (0.65s)483--- PASS: TestSupersededNARStillUploadsListing (0.01s)484 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.03s)485 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.03s)486 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.65s)4872026/11/06 07:10:16 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:53502/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:53502/api/uploads/complete4882026/11/06 07:10:16 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4892026/11/06 07:10:16 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:53502/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:53502/api/uploads/complete490--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4912026/11/06 07:10:16 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4922026/11/06 07:10:16 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:53502/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:53502/api/uploads/complete4932026/11/06 07:10:16 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"494--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)495PASS496Running server tests...497The files belonging to this database system will be owned by user "_tribuchetbld2".498This user must also own the server process.499500The database cluster will be initialized with locale "C".501The default database encoding has accordingly been set to "SQL_ASCII".502The default text search configuration will be set to "english".503504Data page checksums are enabled.505506creating directory /private/var/tb/2/scratch/da980f7a6ee70515/build/postgres243601820/data ... ok507creating subdirectories ... ok508selecting dynamic shared memory implementation ... posix509selecting default "max_connections" ... 100510selecting default "shared_buffers" ... 128MB511selecting default time zone ... UTC512creating configuration files ... ok513running bootstrap script ... ok514performing post-bootstrap initialization ... ok515syncing data to disk ... ok516517initdb: warning: enabling "trust" authentication for local connections518initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.519520Success. You can now start the database server using:521522 pg_ctl -D /private/var/tb/2/scratch/da980f7a6ee70515/build/postgres243601820/data -l logfile start523524/private/var/tb/2/scratch/da980f7a6ee70515/build/postgres243601820:5432 - no response5252026-11-06 07:10:17.406 UTC [80988] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5262026-11-06 07:10:17.406 UTC [80988] LOG: listening on Unix socket "/private/var/tb/2/scratch/da980f7a6ee70515/build/postgres243601820/.s.PGSQL.5432"5272026-11-06 07:10:17.416 UTC [81005] LOG: database system was shut down at 2026-11-06 07:10:17 UTC5282026-11-06 07:10:17.418 UTC [80988] LOG: database system is ready to accept connections529/private/var/tb/2/scratch/da980f7a6ee70515/build/postgres243601820:5432 - accepting connections530{"timestamp":"2026-11-06T07:10:21.620881Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"3cd3f6cd-7b22-4061-b080-e35824ded572","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(8)"}531{"timestamp":"2026-11-06T07:10:21.724825Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"b8df78b9-8b23-4551-8e4a-672817666d36","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(10)"}532=== RUN TestService_AuthMiddleware533=== PAUSE TestService_AuthMiddleware534=== RUN TestService_AuthMiddleware_MTLSProxyHeader535=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader536=== RUN TestService_AuthMiddleware_MTLSBoundSubjects537=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects538=== RUN TestService_ReadAuthMiddleware539=== PAUSE TestService_ReadAuthMiddleware540=== RUN TestService_AuthMiddleware_OIDC541=== PAUSE TestService_AuthMiddleware_OIDC542=== RUN TestService_RequireScope_OIDC543=== PAUSE TestService_RequireScope_OIDC544=== RUN TestService_ReadScope_PublicByDefault545=== PAUSE TestService_ReadScope_PublicByDefault546=== RUN TestCacheConfigHandler547=== PAUSE TestCacheConfigHandler548=== RUN TestCacheStatsHandler549=== PAUSE TestCacheStatsHandler550=== RUN TestClientCADerivations551=== PAUSE TestClientCADerivations552=== RUN TestClientErrorHandling553=== PAUSE TestClientErrorHandling554=== RUN TestClientIntegration555=== PAUSE TestClientIntegration556=== RUN TestClientMultipleUploads557=== PAUSE TestClientMultipleUploads558=== RUN TestClientWithDependencies559=== PAUSE TestClientWithDependencies560=== RUN TestClientSharedPathCommittedMidPush561=== PAUSE TestClientSharedPathCommittedMidPush562=== RUN TestPinProtectsFromGC563=== PAUSE TestPinProtectsFromGC564=== RUN TestClientPushesUseOnePush565=== PAUSE TestClientPushesUseOnePush566=== RUN TestClientFallsBackToClosures567=== PAUSE TestClientFallsBackToClosures568=== RUN TestDeleteClosuresRacingPins569=== PAUSE TestDeleteClosuresRacingPins570=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock571=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock572=== RUN TestResolveDBConnectionString573=== PAUSE TestResolveDBConnectionString574=== RUN TestConnectWaitsForAPeerMigration575=== PAUSE TestConnectWaitsForAPeerMigration576=== RUN TestLeadElectsOneAndHandsOver577=== PAUSE TestLeadElectsOneAndHandsOver578=== RUN TestLeadIncumbentWinsAfterRestart5792026/11/06 07:10:22 INFO lead: acquired remote=192.0.2.1:12345802026/11/06 07:10:22 INFO lead: released remote=192.0.2.1:12345812026/11/06 07:10:22 INFO lead: acquired remote=192.0.2.1:12345822026/11/06 07:10:24 INFO lead: released remote=192.0.2.1:1234583--- PASS: TestLeadIncumbentWinsAfterRestart (2.18s)584=== RUN TestLeadIncumbentAnnouncesAtOnce585=== PAUSE TestLeadIncumbentAnnouncesAtOnce586=== RUN TestLeadEndsOnShutdown587=== PAUSE TestLeadEndsOnShutdown588=== RUN TestLeadEndsWhenItsConnectionHangs5892026/11/06 07:10:24 INFO lead: acquired remote=192.0.2.1:12345902026-11-06 07:10:25.660 UTC [81943] FATAL: terminating connection due to administrator command5912026/11/06 07:10:25 INFO lead: acquired remote=192.0.2.1:12345922026/11/06 07:10:26 WARN lead: lock connection lost error="timeout: context deadline exceeded"5932026/11/06 07:10:26 INFO lead: released remote=192.0.2.1:12345942026/11/06 07:10:27 INFO lead: released remote=192.0.2.1:1234595--- PASS: TestLeadEndsWhenItsConnectionHangs (3.03s)596=== RUN TestGCAdvisoryLockBlocksConcurrentRun597=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun598=== RUN TestGCBugBareHashReferences599=== PAUSE TestGCBugBareHashReferences600=== RUN TestGCMetrics601=== PAUSE TestGCMetrics602=== RUN TestPushDedupSurvivesConcurrentGC603=== PAUSE TestPushDedupSurvivesConcurrentGC604=== RUN TestDeduplicatedObjectsRecordedAsPending605=== PAUSE TestDeduplicatedObjectsRecordedAsPending606=== RUN TestGCSweepSkipsPendingObjects607=== PAUSE TestGCSweepSkipsPendingObjects608=== RUN TestTombstonedObjectOfferedWithoutWaiting609=== PAUSE TestTombstonedObjectOfferedWithoutWaiting610=== RUN TestGCSweepDeliversEachKeyOnce611=== PAUSE TestGCSweepDeliversEachKeyOnce612=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection613=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection614=== RUN TestForceGCDuringPushOffersSweptObject615=== PAUSE TestForceGCDuringPushOffersSweptObject616=== RUN TestFailedS3DeleteKeepsTombstone617=== PAUSE TestFailedS3DeleteKeepsTombstone618=== RUN TestSweepSkipsRowsLockedByPush619=== PAUSE TestSweepSkipsRowsLockedByPush620=== RUN TestRegisterCompletedObjectNeedsPendingRow621=== PAUSE TestRegisterCompletedObjectNeedsPendingRow622=== RUN TestGetExistingObjectsLocksRows623=== PAUSE TestGetExistingObjectsLocksRows624=== RUN TestSweepRechecksPendingAfterLocking625=== PAUSE TestSweepRechecksPendingAfterLocking626=== RUN TestPushWaitsForSweepHoldingRow627=== PAUSE TestPushWaitsForSweepHoldingRow628=== RUN TestCommitRacingPendingCleanupKeepsObjects629=== PAUSE TestCommitRacingPendingCleanupKeepsObjects630=== RUN TestGCEndsOnShutdown631=== PAUSE TestGCEndsOnShutdown632=== RUN TestGCTaskStore_StartNew633=== PAUSE TestGCTaskStore_StartNew634=== RUN TestGCTaskStore_DeduplicateSameParams635=== PAUSE TestGCTaskStore_DeduplicateSameParams636=== RUN TestGCTaskStore_ConflictDifferentParams637=== PAUSE TestGCTaskStore_ConflictDifferentParams638=== RUN TestGCTaskStore_GetEmpty639=== PAUSE TestGCTaskStore_GetEmpty640=== RUN TestGCTaskStore_GetReturnsLatest641=== PAUSE TestGCTaskStore_GetReturnsLatest642=== RUN TestGCTaskStore_CompletedAllowsNewTask643=== PAUSE TestGCTaskStore_CompletedAllowsNewTask644=== RUN TestGCTaskStore_PhaseUpdates645=== PAUSE TestGCTaskStore_PhaseUpdates646=== RUN TestGCTaskStore_Fail647=== PAUSE TestGCTaskStore_Fail648=== RUN TestGracefulShutdownDrainsInflight649=== PAUSE TestGracefulShutdownDrainsInflight650=== RUN TestService_healthCheckHandler651=== PAUSE TestService_healthCheckHandler652=== RUN TestService_readinessHandler653=== PAUSE TestService_readinessHandler654=== RUN TestGenerateLandingPage655=== PAUSE TestGenerateLandingPage656=== RUN TestCacheConfigHandlerMaxNarSize657=== PAUSE TestCacheConfigHandlerMaxNarSize658=== RUN TestCreatePendingClosureRejectsOversizedNAR659=== PAUSE TestCreatePendingClosureRejectsOversizedNAR660=== RUN TestNARDeduplicationMetadataUploadBug661=== PAUSE TestNARDeduplicationMetadataUploadBug662=== RUN TestMetricsInventory663=== PAUSE TestMetricsInventory664=== RUN TestMetricsCommit665=== PAUSE TestMetricsCommit666=== RUN TestService_NativeMTLS667=== PAUSE TestService_NativeMTLS668=== RUN TestServerTLSConfig669=== PAUSE TestServerTLSConfig670=== RUN TestMultipartCleanup671=== PAUSE TestMultipartCleanup672=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded673=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded674=== RUN TestPendingCleanupUsesOneCutoff675=== PAUSE TestPendingCleanupUsesOneCutoff676=== RUN TestObjectStatsTrigger677=== PAUSE TestObjectStatsTrigger678=== RUN TestObjectStatsUpdatedOncePerCommit679=== PAUSE TestObjectStatsUpdatedOncePerCommit680=== RUN TestOrphanedObjectsGC681=== PAUSE TestOrphanedObjectsGC682=== RUN TestOrphanedObjectsGCStressTest683=== PAUSE TestOrphanedObjectsGCStressTest684=== RUN TestCreatePin_ReservedPins685=== PAUSE TestCreatePin_ReservedPins686=== RUN TestPresentReportsOnlyClosureRoots687=== PAUSE TestPresentReportsOnlyClosureRoots688=== RUN TestPresentRefreshesOnlyStaleClosures689=== PAUSE TestPresentRefreshesOnlyStaleClosures690=== RUN TestPresentNotReportedWhileGCDeletesClosure691=== PAUSE TestPresentNotReportedWhileGCDeletesClosure692=== RUN TestParseSingleRange693=== PAUSE TestParseSingleRange694=== RUN TestProxyHeadersOnlyTrustedOnSocket6952026/11/06 07:10:27 INFO Starting HTTP server address=proxy.sock6962026/11/06 07:10:27 INFO Starting HTTP server address=127.0.0.1:537176972026/11/06 07:10:27 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6982026/11/06 07:10:27 INFO Shutdown signal received, draining in-flight requests timeout=10s699--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.85s)700=== RUN TestIsValidCachePath701=== PAUSE TestIsValidCachePath702=== RUN TestReadProxyNarinfo703=== PAUSE TestReadProxyNarinfo704=== RUN TestReadProxyNarinfoAlreadyDecompressed705=== PAUSE TestReadProxyNarinfoAlreadyDecompressed706=== RUN TestReadProxyContentNegotiation707=== PAUSE TestReadProxyContentNegotiation708=== RUN TestReadProxyNarStreaming709=== PAUSE TestReadProxyNarStreaming710=== RUN TestReadProxy404711=== PAUSE TestReadProxy404712=== RUN TestReadProxyInvalidPath713=== PAUSE TestReadProxyInvalidPath714=== RUN TestReadProxyHead715=== PAUSE TestReadProxyHead716=== RUN TestReadProxyOutlastsServerWriteTimeout717=== PAUSE TestReadProxyOutlastsServerWriteTimeout718=== RUN TestReadProxyConditionalGet719=== PAUSE TestReadProxyConditionalGet720=== RUN TestReadProxyRootRedirectsToIndexHTML721=== PAUSE TestReadProxyRootRedirectsToIndexHTML722=== RUN TestReadProxyDisabled723=== PAUSE TestReadProxyDisabled724=== RUN TestReadRedirectNar725=== PAUSE TestReadRedirectNar726=== RUN TestReadRedirectKeepsNarinfoProxied727=== PAUSE TestReadRedirectKeepsNarinfoProxied728=== RUN TestReadProxyRangeRequest729=== PAUSE TestReadProxyRangeRequest730=== RUN TestReadRedirectUsesPublicS3URL731=== PAUSE TestReadRedirectUsesPublicS3URL732=== RUN TestPush_OverlappingRootsStoreOneRowPerKey733=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey734=== RUN TestPush_CompleteCommitsEveryRoot735=== PAUSE TestPush_CompleteCommitsEveryRoot736=== RUN TestPush_RepeatedRootCommitsOnce737=== PAUSE TestPush_RepeatedRootCommitsOnce738=== RUN TestPush_CompleteWaitsForCleanupOfThePush739=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush740=== RUN TestPush_RootsAreLockedInByteOrder741=== PAUSE TestPush_RootsAreLockedInByteOrder742=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit743=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit744=== RUN TestPush_RejectsBadRequests745=== PAUSE TestPush_RejectsBadRequests746=== RUN TestPush_SignsNarinfosOfItsPendingObjects747=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects748=== RUN TestRedundantMultipartUpload749=== PAUSE TestRedundantMultipartUpload750=== RUN TestCompleteMultipartUpload_ErrorButObjectExists751=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists752=== RUN TestCompletedNarNotReofferedAcrossClosures753=== PAUSE TestCompletedNarNotReofferedAcrossClosures754=== RUN TestPresignedUploadRegisteredBeforeCommit755=== PAUSE TestPresignedUploadRegisteredBeforeCommit756=== RUN TestService_Rustfstest757=== PAUSE TestService_Rustfstest758=== RUN TestParseSize759=== PAUSE TestParseSize760=== RUN TestSkippedUploadsHandler761=== PAUSE TestSkippedUploadsHandler762=== RUN TestSystemdListenerNotActivated763--- PASS: TestSystemdListenerNotActivated (0.00s)764=== RUN TestWatchdogBeatsWhenHealthy765--- PASS: TestWatchdogBeatsWhenHealthy (0.04s)766=== RUN TestWatchdogSkipsWhenUnhealthy7672026/11/06 07:10:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/11/06 07:10:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/11/06 07:10:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/06 07:10:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/06 07:10:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/06 07:10:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/06 07:10:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/06 07:10:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/06 07:10:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/11/06 07:10:28 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"777--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)778=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle779=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle780=== RUN TestProxyWriteTimeout781=== PAUSE TestProxyWriteTimeout782=== RUN TestPendingClosureWriteTimeout783=== PAUSE TestPendingClosureWriteTimeout784=== RUN TestIsValidUploadKey785=== PAUSE TestIsValidUploadKey786=== RUN TestUploadHandlersRejectInvalidKeys787=== PAUSE TestUploadHandlersRejectInvalidKeys788=== RUN TestUploadHandlersRejectOversizedBody789=== PAUSE TestUploadHandlersRejectOversizedBody790=== RUN TestService_cleanupPendingClosuresHandler791=== PAUSE TestService_cleanupPendingClosuresHandler792=== RUN TestService_createPendingClosureHandler793=== PAUSE TestService_createPendingClosureHandler794=== RUN TestService_verifyS3Integrity795=== PAUSE TestService_verifyS3Integrity796=== RUN TestService_verifyS3ReuploadsStaleNarinfo797=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo798=== RUN TestCompleteMultipartUnregistered799=== PAUSE TestCompleteMultipartUnregistered800=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT801=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT802=== CONT TestService_AuthMiddleware803=== CONT TestMetricsCommit804=== CONT TestMetricsInventory805=== CONT TestIsValidCachePath806=== RUN TestIsValidCachePath/narinfo807=== PAUSE TestIsValidCachePath/narinfo808=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars809=== CONT TestCompleteMultipartUnregistered810=== CONT TestReadProxyDisabled811=== CONT TestService_Rustfstest812=== CONT TestGCSweepSkipsPendingObjects813=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars814=== RUN TestIsValidCachePath/nar_zst815=== PAUSE TestIsValidCachePath/nar_zst816=== RUN TestIsValidCachePath/nar_xz817=== PAUSE TestIsValidCachePath/nar_xz818=== CONT TestReadProxyNarinfo819=== CONT TestReadRedirectNar820=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT821=== CONT TestReadProxyRootRedirectsToIndexHTML822=== CONT TestReadProxyRangeRequest823=== RUN TestIsValidCachePath/nar_bz2824=== CONT TestReadProxyInvalidPath825=== CONT TestReadProxy404826=== CONT TestReadProxyNarStreaming827=== CONT TestReadProxyContentNegotiation828=== CONT TestReadProxyNarinfoAlreadyDecompressed829=== CONT TestPresignedUploadRegisteredBeforeCommit830=== CONT TestCompletedNarNotReofferedAcrossClosures831=== CONT TestReadProxyConditionalGet832=== CONT TestReadProxyOutlastsServerWriteTimeout833=== CONT TestReadRedirectKeepsNarinfoProxied834=== CONT TestReadProxyHead835=== PAUSE TestIsValidCachePath/nar_bz2836=== RUN TestIsValidCachePath/nar_uncompressed837=== PAUSE TestIsValidCachePath/nar_uncompressed838=== RUN TestIsValidCachePath/ls839=== PAUSE TestIsValidCachePath/ls840=== RUN TestIsValidCachePath/log841=== PAUSE TestIsValidCachePath/log842=== RUN TestIsValidCachePath/realisation843=== PAUSE TestIsValidCachePath/realisation844=== RUN TestIsValidCachePath/nix-cache-info845=== PAUSE TestIsValidCachePath/nix-cache-info846=== RUN TestIsValidCachePath/index.html847=== PAUSE TestIsValidCachePath/index.html848=== RUN TestIsValidCachePath/traversal_parent849=== PAUSE TestIsValidCachePath/traversal_parent850=== RUN TestIsValidCachePath/traversal_in_middle851=== PAUSE TestIsValidCachePath/traversal_in_middle852=== RUN TestIsValidCachePath/invalid_char_e853=== PAUSE TestIsValidCachePath/invalid_char_e854=== RUN TestIsValidCachePath/invalid_char_u855=== PAUSE TestIsValidCachePath/invalid_char_u856=== RUN TestIsValidCachePath/random_path857=== PAUSE TestIsValidCachePath/random_path858=== RUN TestIsValidCachePath/empty859=== PAUSE TestIsValidCachePath/empty860=== RUN TestIsValidCachePath/leading_slash861=== PAUSE TestIsValidCachePath/leading_slash862=== RUN TestIsValidCachePath/wrong_extension863=== PAUSE TestIsValidCachePath/wrong_extension864=== RUN TestIsValidCachePath/short_hash865=== PAUSE TestIsValidCachePath/short_hash866=== CONT TestCompleteMultipartUpload_ErrorButObjectExists8672026/11/06 07:10:30 INFO Received push request method=POST path=/api/pushes8682026/11/06 07:10:30 INFO Received complete push request method=POST path=/api/pushes/1/complete8692026/11/06 07:10:30 INFO Completed push id=1 objects=4 duration=81.898708ms8702026/11/06 07:10:31 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete8712026/11/06 07:10:31 INFO Completed upload id=2 objects=2 duration=31.219875ms872--- PASS: TestMetricsCommit (2.79s)873=== CONT TestRedundantMultipartUpload8742026/11/06 07:10:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete8752026/11/06 07:10:31 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst876--- PASS: TestCompleteMultipartUnregistered (3.05s)877=== CONT TestPush_SignsNarinfosOfItsPendingObjects878--- PASS: TestReadProxyRangeRequest (4.23s)879=== CONT TestPush_RejectsBadRequests880--- PASS: TestMetricsInventory (4.83s)881=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit882--- PASS: TestReadRedirectNar (5.13s)883=== CONT TestPush_RootsAreLockedInByteOrder8842026/11/06 07:10:33 INFO Received uploads request method=POST path=/api/pending_closures885--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (5.49s)886=== CONT TestPush_CompleteWaitsForCleanupOfThePush8872026/11/06 07:10:33 INFO Received uploads request method=POST path=/api/pending_closures8882026/11/06 07:10:33 INFO Aborted multipart uploads count=0 kept=08892026/11/06 07:10:33 WARN Force mode enabled - objects will be deleted immediately without grace period8902026/11/06 07:10:33 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=08912026/11/06 07:10:33 INFO Vacuumed table table=pending_closures892--- PASS: TestService_Rustfstest (5.74s)893=== CONT TestPush_RepeatedRootCommitsOnce8942026/11/06 07:10:34 INFO Vacuumed table table=pending_objects8952026/11/06 07:10:34 INFO Vacuumed table table=multipart_uploads8962026/11/06 07:10:34 INFO Vacuumed table table=closures8972026/11/06 07:10:34 INFO Vacuumed table table=objects898--- PASS: TestGCSweepSkipsPendingObjects (5.80s)899=== CONT TestPush_CompleteCommitsEveryRoot900--- PASS: TestReadProxyDisabled (5.93s)901=== CONT TestPush_OverlappingRootsStoreOneRowPerKey9022026/11/06 07:10:34 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"903--- PASS: TestService_AuthMiddleware (6.11s)904=== CONT TestReadRedirectUsesPublicS3URL905--- PASS: TestReadProxyConditionalGet (6.51s)906=== CONT TestService_verifyS3ReuploadsStaleNarinfo907=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed908=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed909=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed910=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed911=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost912=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost913=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed914=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed915=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed916=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed917=== CONT TestService_verifyS3Integrity9182026/11/06 07:10:34 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>919--- PASS: TestReadProxyNarinfo (6.54s)920=== CONT TestService_createPendingClosureHandler9212026/11/06 07:10:35 INFO Received uploads request method=POST path=/api/pending_closures922--- PASS: TestReadProxyInvalidPath (7.20s)923=== CONT TestService_cleanupPendingClosuresHandler9242026/11/06 07:10:35 INFO Received uploads request method=POST path=/api/pending_closures9252026/11/06 07:10:35 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst9262026/11/06 07:10:35 INFO Received uploads request method=POST path=/api/pending_closures927--- PASS: TestPresignedUploadRegisteredBeforeCommit (7.53s)928=== CONT TestUploadHandlersRejectOversizedBody929=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure930=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure931=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart932=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart933=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts934=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts935=== CONT TestUploadHandlersRejectInvalidKeys936=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info937=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info938=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal939=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal940=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key941=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key942=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key943=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key944=== CONT TestIsValidUploadKey945=== RUN TestIsValidUploadKey/narinfo946=== PAUSE TestIsValidUploadKey/narinfo947=== RUN TestIsValidUploadKey/nar_zst948=== PAUSE TestIsValidUploadKey/nar_zst949=== RUN TestIsValidUploadKey/nar_xz950=== PAUSE TestIsValidUploadKey/nar_xz951=== RUN TestIsValidUploadKey/nar_plain952=== PAUSE TestIsValidUploadKey/nar_plain953=== RUN TestIsValidUploadKey/listing954=== PAUSE TestIsValidUploadKey/listing955=== RUN TestIsValidUploadKey/build_log956=== PAUSE TestIsValidUploadKey/build_log957=== RUN TestIsValidUploadKey/build_log_home-manager_file958=== PAUSE TestIsValidUploadKey/build_log_home-manager_file959=== RUN TestIsValidUploadKey/build_log_plus_in_name960=== PAUSE TestIsValidUploadKey/build_log_plus_in_name961=== RUN TestIsValidUploadKey/build_log_question_mark962=== PAUSE TestIsValidUploadKey/build_log_question_mark963=== RUN TestIsValidUploadKey/build_log_equals964=== PAUSE TestIsValidUploadKey/build_log_equals965=== RUN TestIsValidUploadKey/realisation966=== PAUSE TestIsValidUploadKey/realisation967=== RUN TestIsValidUploadKey/realisation_plus_in_output968=== PAUSE TestIsValidUploadKey/realisation_plus_in_output969=== RUN TestIsValidUploadKey/nix-cache-info970=== PAUSE TestIsValidUploadKey/nix-cache-info971=== RUN TestIsValidUploadKey/index.html972=== PAUSE TestIsValidUploadKey/index.html973=== RUN TestIsValidUploadKey/narinfo_key,_nar_type974=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type975=== RUN TestIsValidUploadKey/nar_key,_narinfo_type976=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type977=== RUN TestIsValidUploadKey/listing_key,_narinfo_type978=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type979=== RUN TestIsValidUploadKey/traversal980=== PAUSE TestIsValidUploadKey/traversal981=== RUN TestIsValidUploadKey/traversal_nar982=== PAUSE TestIsValidUploadKey/traversal_nar983=== RUN TestIsValidUploadKey/absolute984=== PAUSE TestIsValidUploadKey/absolute985=== RUN TestIsValidUploadKey/empty_key986=== PAUSE TestIsValidUploadKey/empty_key987=== RUN TestIsValidUploadKey/unknown_type988=== PAUSE TestIsValidUploadKey/unknown_type989=== CONT TestPendingClosureWriteTimeout990=== RUN TestPendingClosureWriteTimeout/empty991=== PAUSE TestPendingClosureWriteTimeout/empty992=== RUN TestPendingClosureWriteTimeout/400_objects993=== PAUSE TestPendingClosureWriteTimeout/400_objects994=== RUN TestPendingClosureWriteTimeout/670k_objects995=== PAUSE TestPendingClosureWriteTimeout/670k_objects996=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline997=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline998=== CONT TestProxyWriteTimeout999=== RUN TestProxyWriteTimeout/narinfo1000=== PAUSE TestProxyWriteTimeout/narinfo1001=== RUN TestProxyWriteTimeout/1_GiB_nar1002=== PAUSE TestProxyWriteTimeout/1_GiB_nar1003=== RUN TestProxyWriteTimeout/10_GiB_nar1004=== PAUSE TestProxyWriteTimeout/10_GiB_nar1005=== RUN TestProxyWriteTimeout/unknown_size1006=== PAUSE TestProxyWriteTimeout/unknown_size1007=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1008--- PASS: TestReadProxyContentNegotiation (8.13s)1009=== CONT TestSkippedUploadsHandler10102026/11/06 07:10:36 INFO Client skipped oversized paths paths=3 nar_bytes=50000000001011--- PASS: TestSkippedUploadsHandler (0.01s)1012=== CONT TestParseSize1013--- PASS: TestParseSize (0.00s)1014=== CONT TestOrphanedObjectsGC1015--- PASS: TestReadRedirectKeepsNarinfoProxied (8.30s)1016=== CONT TestParseSingleRange1017=== RUN TestParseSingleRange/none1018=== PAUSE TestParseSingleRange/none1019=== RUN TestParseSingleRange/unknown_unit1020=== PAUSE TestParseSingleRange/unknown_unit1021=== RUN TestParseSingleRange/multi-range_ignored1022=== PAUSE TestParseSingleRange/multi-range_ignored1023=== RUN TestParseSingleRange/malformed_no_dash1024=== PAUSE TestParseSingleRange/malformed_no_dash1025=== RUN TestParseSingleRange/malformed_both_empty1026=== PAUSE TestParseSingleRange/malformed_both_empty1027=== RUN TestParseSingleRange/malformed_end_before_start1028=== PAUSE TestParseSingleRange/malformed_end_before_start1029=== RUN TestParseSingleRange/closed1030=== PAUSE TestParseSingleRange/closed1031=== RUN TestParseSingleRange/open-ended1032=== PAUSE TestParseSingleRange/open-ended1033=== RUN TestParseSingleRange/end_clamped_to_size1034=== PAUSE TestParseSingleRange/end_clamped_to_size1035=== RUN TestParseSingleRange/suffix1036=== PAUSE TestParseSingleRange/suffix1037=== RUN TestParseSingleRange/suffix_exceeds_size1038=== PAUSE TestParseSingleRange/suffix_exceeds_size1039=== RUN TestParseSingleRange/single_byte1040=== PAUSE TestParseSingleRange/single_byte1041=== RUN TestParseSingleRange/start_past_EOF1042=== PAUSE TestParseSingleRange/start_past_EOF1043=== RUN TestParseSingleRange/start_far_past_EOF1044=== PAUSE TestParseSingleRange/start_far_past_EOF1045=== CONT TestPresentNotReportedWhileGCDeletesClosure1046=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1047=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1048=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1049=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1050=== CONT TestPresentRefreshesOnlyStaleClosures1051--- PASS: TestReadProxy404 (8.55s)1052=== CONT TestPresentReportsOnlyClosureRoots1053--- PASS: TestReadProxyRootRedirectsToIndexHTML (8.60s)1054=== CONT TestCreatePin_ReservedPins10552026/11/06 07:10:37 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53802/oidc10562026/11/06 07:10:37 INFO Received uploads request method=POST path=/api/pending_closures10572026/11/06 07:10:38 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1058--- PASS: TestReadProxyOutlastsServerWriteTimeout (11.07s)1059=== CONT TestOrphanedObjectsGCStressTest10602026/11/06 07:10:39 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LjY2Nzg2NTc3LTY5MzYtNDYzMi1hMzc5LTk3Y2ZkNDZlY2Y3ZXgxNzkzOTQ5MDM1MjgwMDMwMDAw parts=1210612026/11/06 07:10:39 INFO Received uploads request method=POST path=/api/pending_closures1062--- PASS: TestCompletedNarNotReofferedAcrossClosures (11.29s)1063=== CONT TestGCTaskStore_DeduplicateSameParams1064--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1065=== CONT TestNARDeduplicationMetadataUploadBug10662026/11/06 07:10:39 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10672026/11/06 07:10:39 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LjU0OTI5YzZkLWJiYTctNGVlMi05N2Y3LTcwNGFkNzY4MzQ0ZXgxNzkzOTQ5MDM5MzMzMzU2MDAw1068--- PASS: TestReadProxyHead (11.57s)1069=== CONT TestCreatePendingClosureRejectsOversizedNAR10702026/11/06 07:10:39 INFO Received uploads request method=POST path=/api/pending_closures1071--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1072=== CONT TestCacheConfigHandlerMaxNarSize1073--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1074=== CONT TestGenerateLandingPage1075--- PASS: TestGenerateLandingPage (0.01s)1076=== CONT TestService_readinessHandler10772026/11/06 07:10:39 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LjU0OTI5YzZkLWJiYTctNGVlMi05N2Y3LTcwNGFkNzY4MzQ0ZXgxNzkzOTQ5MDM5MzMzMzU2MDAw parts=11078--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (11.61s)1079=== CONT TestService_healthCheckHandler1080--- PASS: TestReadProxyNarStreaming (11.95s)1081=== CONT TestGracefulShutdownDrainsInflight10822026/11/06 07:10:40 INFO Starting HTTP server address=127.0.0.1:5381610832026/11/06 07:10:40 INFO Shutdown signal received, draining in-flight requests timeout=10s1084--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1085=== CONT TestGCTaskStore_Fail1086--- PASS: TestGCTaskStore_Fail (0.00s)1087=== CONT TestGCTaskStore_PhaseUpdates1088--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1089=== CONT TestGCTaskStore_CompletedAllowsNewTask1090--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1091=== CONT TestGCTaskStore_GetReturnsLatest1092--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1093=== CONT TestGCTaskStore_GetEmpty1094--- PASS: TestGCTaskStore_GetEmpty (0.00s)1095=== CONT TestGCTaskStore_ConflictDifferentParams1096--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1097=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1098--- PASS: TestReadProxyNarinfoAlreadyDecompressed (12.37s)1099=== CONT TestObjectStatsUpdatedOncePerCommit11002026/11/06 07:10:40 INFO Received uploads request method=POST path=/api/pending_closures11012026/11/06 07:10:41 INFO Received uploads request method=POST path=/api/pending_closures11022026/11/06 07:10:41 INFO Received push request method=POST path=/api/pushes11032026/11/06 07:10:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11042026/11/06 07:10:41 INFO Signed narinfos id=1 count=111052026/11/06 07:10:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11062026/11/06 07:10:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11072026/11/06 07:10:41 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"11082026/11/06 07:10:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11092026/11/06 07:10:41 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"11102026/11/06 07:10:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11112026/11/06 07:10:41 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=111122026/11/06 07:10:41 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11132026/11/06 07:10:41 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1114--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (10.16s)1115=== CONT TestObjectStatsTrigger1116=== RUN TestPush_RejectsBadRequests/no_objects1117=== PAUSE TestPush_RejectsBadRequests/no_objects1118=== RUN TestPush_RejectsBadRequests/bad_root1119=== PAUSE TestPush_RejectsBadRequests/bad_root1120=== RUN TestPush_RejectsBadRequests/root_not_in_objects1121=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1122=== RUN TestPush_RejectsBadRequests/no_roots1123=== PAUSE TestPush_RejectsBadRequests/no_roots1124=== CONT TestPendingCleanupUsesOneCutoff11252026/11/06 07:10:42 INFO Received push request method=POST path=/api/pushes11262026-11-06 07:10:42.467 UTC [82661] ERROR: could not obtain lock on row in relation "closures"11272026-11-06 07:10:42.467 UTC [82661] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11282026-11-06 07:10:42.474 UTC [82661] ERROR: could not obtain lock on row in relation "closures"11292026-11-06 07:10:42.474 UTC [82661] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11302026-11-06 07:10:42.476 UTC [82661] ERROR: could not obtain lock on row in relation "closures"11312026-11-06 07:10:42.476 UTC [82661] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11322026-11-06 07:10:42.484 UTC [82661] ERROR: could not obtain lock on row in relation "closures"11332026-11-06 07:10:42.484 UTC [82661] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11342026-11-06 07:10:42.492 UTC [82661] ERROR: could not obtain lock on row in relation "closures"11352026-11-06 07:10:42.492 UTC [82661] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1136--- PASS: TestPush_RootsAreLockedInByteOrder (9.20s)1137=== CONT TestRegisterCompletedObjectNeedsPendingRow11382026/11/06 07:10:42 INFO Received push request method=POST path=/api/pushes11392026/11/06 07:10:42 INFO Received complete push request method=POST path=/api/pushes/1/complete11402026/11/06 07:10:43 INFO Completed push id=1 objects=4 duration=106.52575ms11412026/11/06 07:10:43 INFO Received push request method=POST path=/api/pushes11422026/11/06 07:10:43 INFO Aborted multipart uploads count=0 kept=011432026/11/06 07:10:43 WARN Force mode enabled - objects will be deleted immediately without grace period11442026/11/06 07:10:43 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=011452026/11/06 07:10:43 INFO Received push request method=POST path=/api/pushes11462026/11/06 07:10:43 INFO Vacuumed table table=pending_closures11472026/11/06 07:10:43 INFO Vacuumed table table=pending_objects11482026/11/06 07:10:43 INFO Vacuumed table table=multipart_uploads11492026/11/06 07:10:43 INFO Vacuumed table table=closures11502026/11/06 07:10:43 INFO Vacuumed table table=objects11512026/11/06 07:10:43 INFO Received complete push request method=POST path=/api/pushes/2/complete11522026/11/06 07:10:43 INFO Completed push id=2 objects=4 duration=14.383917ms1153--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (10.35s)1154=== CONT TestPinProtectsFromGC11552026/11/06 07:10:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11562026-11-06 07:10:43.721 UTC [83159] ERROR: Push does not exist: id=111572026-11-06 07:10:43.721 UTC [83159] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11582026-11-06 07:10:43.721 UTC [83159] STATEMENT: SELECT commit_push($1)1159--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (9.97s)1160=== CONT TestDeduplicatedObjectsRecordedAsPending11612026/11/06 07:10:43 INFO Received push request method=POST path=/api/pushes11622026/11/06 07:10:43 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LmY0YjFkMjNlLWM0ZjYtNDFhYS1iYTk5LTEyYmY5NjExOWE0OXgxNzkzOTQ5MDQwOTc2NjgzMDAw parts=1211632026/11/06 07:10:43 INFO Received uploads request method=POST path=/api/pending_closures11642026/11/06 07:10:43 INFO Received uploads request method=POST path=/api/pending_closures11652026/11/06 07:10:44 INFO Received complete push request method=POST path=/api/pushes/1/complete11662026/11/06 07:10:44 INFO Completed push id=1 objects=4 duration=81.077792ms1167--- PASS: TestPush_RepeatedRootCommitsOnce (10.08s)1168=== CONT TestPushDedupSurvivesConcurrentGC11692026/11/06 07:10:44 INFO Received push request method=POST path=/api/pushes11702026/11/06 07:10:44 INFO Received complete push request method=POST path=/api/pushes/1/complete11712026/11/06 07:10:44 INFO Completed push id=1 objects=6 duration=62.728584ms1172--- PASS: TestPush_CompleteCommitsEveryRoot (10.33s)1173=== CONT TestGCTaskStore_StartNew1174--- PASS: TestGCTaskStore_StartNew (0.00s)1175=== CONT TestGCMetrics11762026/11/06 07:10:44 INFO Received push request method=POST path=/api/pushes1177--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (10.68s)1178=== CONT TestGCEndsOnShutdown1179=== RUN TestGCEndsOnShutdown/before_the_run1180=== PAUSE TestGCEndsOnShutdown/before_the_run1181=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1182=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1183=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1184=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1185=== CONT TestGCBugBareHashReferences1186--- PASS: TestReadRedirectUsesPublicS3URL (10.76s)1187=== CONT TestCommitRacingPendingCleanupKeepsObjects11882026/11/06 07:10:45 INFO Received uploads request method=POST path=/api/pending_closures11892026/11/06 07:10:45 INFO Received uploads request method=POST path=/api/pending_closures11902026/11/06 07:10:45 INFO Received uploads request method=POST path=/api/pending_closures11912026/11/06 07:10:45 INFO Received uploads request method=POST path=/api/pending_closures11922026/11/06 07:10:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11932026/11/06 07:10:46 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LjA3MDNjMzY3LWFhOWUtNGYzMy04MGU1LTIwZjExZjI0MzYxOXgxNzkzOTQ5MDQzODg4Nzk1MDAw error="Get \"http://127.0.0.1:1/bucket28/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11942026/11/06 07:10:46 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LjYwMDcxNjBlLTVmNTEtNDhmNi1iZGE3LWNlZTRkOWNmMDY0OXgxNzkzOTQ5MDQzODMzNjc1MDAw parts=1211952026/11/06 07:10:46 INFO Received cleanup request method=DELETE path=/api/pending_closures11962026/11/06 07:10:46 INFO Aborted multipart uploads count=1 kept=011972026/11/06 07:10:46 INFO Received cleanup request method=DELETE path=/api/pending_closures1198--- PASS: TestRedundantMultipartUpload (15.24s)1199=== CONT TestGCAdvisoryLockBlocksConcurrentRun12002026/11/06 07:10:46 INFO Aborted multipart uploads count=0 kept=012012026/11/06 07:10:46 INFO Received uploads request method=POST path=/api/pending_closures12022026/11/06 07:10:46 INFO Received cleanup request method=DELETE path=/api/pending_closures12032026/11/06 07:10:46 INFO Aborted multipart uploads count=1 kept=012042026/11/06 07:10:46 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12052026-11-06 07:10:46.569 UTC [82783] ERROR: Closure does not exist: id=112062026-11-06 07:10:46.569 UTC [82783] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE12072026-11-06 07:10:46.569 UTC [82783] STATEMENT: -- name: CommitPendingClosure :one1208 SELECT commit_pending_closure($1::bigint)::bigint1209 1210--- PASS: TestService_cleanupPendingClosuresHandler (11.11s)1211=== CONT TestPushWaitsForSweepHoldingRow1212--- PASS: TestPresentRefreshesOnlyStaleClosures (10.88s)1213=== CONT TestLeadEndsOnShutdown12142026/11/06 07:10:47 INFO Received uploads request method=POST path=/api/pending_closures12152026/11/06 07:10:47 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12162026/11/06 07:10:48 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LjZmN2VlMTRkLWQ3YzMtNDkzNC04MjFiLWQ0YWUxN2MwNDEzZHgxNzkzOTQ5MDQ1NTE3NDM4MDAw parts=1012172026/11/06 07:10:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12182026/11/06 07:10:48 INFO Completed upload id=1 objects=2 duration=26.527833ms12192026/11/06 07:10:48 INFO Received uploads request method=POST path=/api/pending_closures12202026/11/06 07:10:48 INFO Received uploads request method=POST path=/api/pending_closures12212026/11/06 07:10:48 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo12222026/11/06 07:10:48 WARN Found objects in DB but missing from S3, will re-upload count=11223--- PASS: TestService_verifyS3Integrity (13.34s)1224=== CONT TestSweepRechecksPendingAfterLocking12252026/11/06 07:10:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1226--- PASS: TestPresentReportsOnlyClosureRoots (11.55s)1227=== CONT TestGetExistingObjectsLocksRows12282026/11/06 07:10:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12292026/11/06 07:10:48 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LmFiNDI0NDRiLWQzZjUtNDM5OC04YWI3LTI4NDMwOTgxYjk0OHgxNzkzOTQ5MDQ1ODg3Mjc1MDAw parts=1012302026/11/06 07:10:48 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete12312026/11/06 07:10:48 INFO Completed upload id=1 objects=2 duration=23.410666ms12322026/11/06 07:10:48 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000012332026/11/06 07:10:48 INFO Received uploads request method=POST path=/api/pending_closures12342026/11/06 07:10:48 INFO Starting cleanup of old closures method=DELETE path=/api/closures12352026/11/06 07:10:48 INFO Aborted multipart uploads count=0 kept=012362026/11/06 07:10:48 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=012372026/11/06 07:10:48 INFO Vacuumed table table=pending_closures12382026/11/06 07:10:48 INFO Vacuumed table table=pending_objects12392026/11/06 07:10:48 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12402026/11/06 07:10:48 WARN Refused reserved pin name=worker-x86_64-linux12412026/11/06 07:10:48 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12422026/11/06 07:10:48 INFO Received create pin request method=POST path=/api/pins/my-app12432026/11/06 07:10:48 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux12442026/11/06 07:10:48 INFO Vacuumed table table=multipart_uploads1245--- PASS: TestCreatePin_ReservedPins (12.02s)1246=== CONT TestServerTLSConfig1247=== RUN TestServerTLSConfig/no_client_CA1248=== PAUSE TestServerTLSConfig/no_client_CA1249=== RUN TestServerTLSConfig/missing_CA_file1250=== PAUSE TestServerTLSConfig/missing_CA_file1251=== RUN TestServerTLSConfig/not_a_PEM_file1252=== PAUSE TestServerTLSConfig/not_a_PEM_file1253=== CONT TestMultipartCleanup12542026/11/06 07:10:48 INFO Vacuumed table table=closures12552026/11/06 07:10:48 INFO Vacuumed table table=objects12562026/11/06 07:10:48 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001257--- PASS: TestService_createPendingClosureHandler (14.15s)1258=== CONT TestLeadIncumbentAnnouncesAtOnce1259=== NAME TestOrphanedObjectsGC1260 orphaned_objects_gc_test.go:287: GC Test Summary:1261 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1262 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1263 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1264 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1265 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1266--- PASS: TestOrphanedObjectsGC (13.16s)1267=== CONT TestLeadElectsOneAndHandsOver1268--- PASS: TestService_healthCheckHandler (10.26s)1269=== CONT TestConnectWaitsForAPeerMigration1270=== NAME TestNARDeduplicationMetadataUploadBug1271 metadata_upload_test.go:48: First store path: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestNARDeduplicationMetadataUploadBug2549645279/001/store/2gajhdy760c0ys9lyf2247gnym360rlk-file1.txt12722026/11/06 07:10:50 INFO Received push request method=POST path=/api/pushes12732026/11/06 07:10:50 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12742026/11/06 07:10:50 INFO Uploading 2gajhdy760c0ys9lyf2247gnym360rlk-file1.txt (160B)12752026/11/06 07:10:50 WARN Failed to register uploaded object key=2gajhdy760c0ys9lyf2247gnym360rlk.ls error="server returned 404: 404 page not found\n"12762026/11/06 07:10:50 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12772026/11/06 07:10:50 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12782026/11/06 07:10:50 INFO Signed narinfos id=1 count=112792026/11/06 07:10:50 INFO Uploading 1 narinfos12802026/11/06 07:10:50 WARN readiness check failed error="closed pool"1281--- PASS: TestService_readinessHandler (10.59s)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_configured12932026/11/06 07:10:50 INFO Received complete push request method=POST path=/api/pushes/1/complete1294=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock12952026/11/06 07:10:50 WARN Failed to register uploaded object key=2gajhdy760c0ys9lyf2247gnym360rlk.narinfo error="server returned 404: 404 page not found\n"12962026/11/06 07:10:50 INFO Completed push id=1 objects=3 duration=37.974667ms12972026/11/06 07:10:50 INFO Upload complete. (325ms)1298=== NAME TestNARDeduplicationMetadataUploadBug1299 metadata_upload_test.go:54: Retrieved narinfo from S3:1300 StorePath: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestNARDeduplicationMetadataUploadBug2549645279/001/store/2gajhdy760c0ys9lyf2247gnym360rlk-file1.txt1301 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1302 Compression: zstd1303 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1304 NarSize: 1601305 References: 1306 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1307 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1308 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1309 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1310 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/2/scratch/da980f7a6ee70515/build/TestNARDeduplicationMetadataUploadBug2549645279/001/store/smp32fg2yar6xkhs2jwar0xz2vr13rj9-file2.txt13112026/11/06 07:10:50 INFO Received uploads request method=POST path=/api/pending_closures13122026/11/06 07:10:50 INFO Received push request method=POST path=/api/pushes13132026/11/06 07:10:50 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1314--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (10.58s)1315=== CONT TestDeleteClosuresRacingPins13162026/11/06 07:10:50 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13172026/11/06 07:10:50 INFO Signed narinfos id=2 count=113182026/11/06 07:10:50 WARN Failed to register uploaded object key=smp32fg2yar6xkhs2jwar0xz2vr13rj9.ls error="server returned 404: 404 page not found\n"13192026/11/06 07:10:50 INFO Uploading 1 narinfos13202026/11/06 07:10:50 INFO Received complete push request method=POST path=/api/pushes/2/complete13212026/11/06 07:10:50 WARN Failed to register uploaded object key=smp32fg2yar6xkhs2jwar0xz2vr13rj9.narinfo error="server returned 404: 404 page not found\n"13222026/11/06 07:10:50 INFO Completed push id=2 objects=3 duration=1.666791ms13232026/11/06 07:10:51 INFO Upload complete. (210ms)1324=== NAME TestNARDeduplicationMetadataUploadBug1325 metadata_upload_test.go:76: Retrieved narinfo from S3:1326 StorePath: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestNARDeduplicationMetadataUploadBug2549645279/001/store/smp32fg2yar6xkhs2jwar0xz2vr13rj9-file2.txt1327 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1328 Compression: zstd1329 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1330 NarSize: 1601331 References: 1332 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1333 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1334 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1335 {"version":1,"root":{"type":"regular","size":44}}1336--- PASS: TestNARDeduplicationMetadataUploadBug (11.53s)1337=== CONT TestClientFallsBackToClosures1338--- PASS: TestObjectStatsUpdatedOncePerCommit (10.83s)1339=== CONT TestClientPushesUseOnePush1340--- PASS: TestObjectStatsTrigger (10.19s)1341=== CONT TestCacheStatsHandler13422026/11/06 07:10:51 INFO Received uploads request method=POST path=/api/pending_closures13432026/11/06 07:10:51 INFO Received uploads request method=POST path=/api/pending_closures13442026/11/06 07:10:52 INFO Received cleanup request method=DELETE path=/api/pending_closures1345--- PASS: TestRegisterCompletedObjectNeedsPendingRow (9.71s)1346=== CONT TestService_NativeMTLS13472026/11/06 07:10:52 WARN Rate limiter enabled after throttle name=s3-test rate=513482026/11/06 07:10:52 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1349=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1350 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101351 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001352--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (16.41s)1353=== CONT TestClientSharedPathCommittedMidPush13542026/11/06 07:10:52 INFO Received uploads request method=POST path=/api/pending_closures1355=== NAME TestPinProtectsFromGC1356 client_integration_test.go:778: Pinned store path: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestPinProtectsFromGC2938947068/001/store/vlkf076y8hm605x4bd0g15spmll9r7gc-pinned-file.txt1357 client_integration_test.go:779: Unpinned store path: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestPinProtectsFromGC2938947068/001/store/z42qrkgf70q8pqkyy2y36dw7zrp54db7-unpinned-file.txt1358--- PASS: TestDeduplicatedObjectsRecordedAsPending (9.32s)1359=== CONT TestClientWithDependencies13602026/11/06 07:10:53 INFO Received push request method=POST path=/api/pushes13612026/11/06 07:10:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13622026/11/06 07:10:53 INFO Uploading vlkf076y8hm605x4bd0g15spmll9r7gc-pinned-file.txt (128B)13632026/11/06 07:10:53 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"13642026/11/06 07:10:53 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13652026/11/06 07:10:53 WARN Failed to register uploaded object key=vlkf076y8hm605x4bd0g15spmll9r7gc.ls error="server returned 404: 404 page not found\n"13662026/11/06 07:10:53 INFO Signed narinfos id=1 count=113672026/11/06 07:10:53 INFO Uploading 1 narinfos13682026/11/06 07:10:53 INFO Received complete push request method=POST path=/api/pushes/1/complete13692026/11/06 07:10:53 WARN Failed to register uploaded object key=vlkf076y8hm605x4bd0g15spmll9r7gc.narinfo error="server returned 404: 404 page not found\n"13702026/11/06 07:10:53 INFO Completed push id=1 objects=3 duration=52.602792ms13712026/11/06 07:10:53 INFO Upload complete. (322ms)13722026/11/06 07:10:53 INFO Received push request method=POST path=/api/pushes13732026/11/06 07:10:53 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)13742026/11/06 07:10:53 INFO Uploading z42qrkgf70q8pqkyy2y36dw7zrp54db7-unpinned-file.txt (128B)13752026/11/06 07:10:53 INFO Received uploads request method=POST path=/api/pending_closures13762026/11/06 07:10:53 WARN Failed to register uploaded object key=z42qrkgf70q8pqkyy2y36dw7zrp54db7.ls error="server returned 404: 404 page not found\n"13772026/11/06 07:10:53 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign13782026/11/06 07:10:53 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"13792026/11/06 07:10:53 INFO Signed narinfos id=2 count=113802026/11/06 07:10:53 INFO Uploading 1 narinfos13812026/11/06 07:10:53 INFO Received complete push request method=POST path=/api/pushes/2/complete13822026/11/06 07:10:53 WARN Failed to register uploaded object key=z42qrkgf70q8pqkyy2y36dw7zrp54db7.narinfo error="server returned 404: 404 page not found\n"13832026/11/06 07:10:53 INFO Completed push id=2 objects=3 duration=905.916µs13842026/11/06 07:10:53 INFO Upload complete. (242ms)13852026/11/06 07:10:53 INFO Starting cleanup of old closures method=DELETE path=/api/closures13862026/11/06 07:10:53 INFO Aborted multipart uploads count=0 kept=013872026/11/06 07:10:53 INFO Garbage collection started13882026/11/06 07:10:53 INFO Aborted multipart uploads count=0 kept=013892026/11/06 07:10:53 INFO Aborted multipart uploads count=0 kept=013902026/11/06 07:10:53 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=013912026/11/06 07:10:53 WARN Force mode enabled - objects will be deleted immediately without grace period13922026/11/06 07:10:53 WARN Force mode enabled - objects will be deleted immediately without grace period13932026/11/06 07:10:53 INFO Vacuumed table table=pending_closures13942026/11/06 07:10:53 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=013952026/11/06 07:10:53 INFO Vacuumed table table=pending_closures13962026/11/06 07:10:53 INFO Vacuumed table table=pending_objects13972026/11/06 07:10:53 INFO Vacuumed table table=multipart_uploads13982026/11/06 07:10:53 INFO Vacuumed table table=pending_objects13992026/11/06 07:10:53 INFO Vacuumed table table=closures14002026/11/06 07:10:53 INFO Vacuumed table table=multipart_uploads14012026/11/06 07:10:53 INFO Vacuumed table table=objects1402--- PASS: TestGCMetrics (9.48s)1403=== CONT TestClientMultipleUploads14042026/11/06 07:10:54 INFO Vacuumed table table=closures14052026/11/06 07:10:54 INFO Vacuumed table table=objects14062026/11/06 07:10:54 INFO Aborted multipart uploads count=0 kept=014072026/11/06 07:10:54 WARN Force mode enabled - objects will be deleted immediately without grace period14082026/11/06 07:10:54 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=014092026/11/06 07:10:54 INFO Vacuumed table table=pending_closures14102026/11/06 07:10:54 INFO Vacuumed table table=pending_objects14112026/11/06 07:10:54 INFO Vacuumed table table=multipart_uploads14122026/11/06 07:10:54 INFO Vacuumed table table=closures14132026/11/06 07:10:54 INFO Vacuumed table table=objects1414--- PASS: TestPushDedupSurvivesConcurrentGC (10.16s)1415=== CONT TestClientIntegration14162026/11/06 07:10:54 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=014172026/11/06 07:10:54 INFO Vacuumed table table=pending_closures14182026/11/06 07:10:54 INFO Vacuumed table table=pending_objects14192026/11/06 07:10:54 INFO Vacuumed table table=multipart_uploads1420--- PASS: TestGCBugBareHashReferences (9.66s)1421=== CONT TestClientErrorHandling1422=== RUN TestClientErrorHandling/InvalidStorePath1423=== PAUSE TestClientErrorHandling/InvalidStorePath1424=== RUN TestClientErrorHandling/InvalidAuthToken1425=== PAUSE TestClientErrorHandling/InvalidAuthToken1426=== RUN TestClientErrorHandling/ServerNotAvailable1427=== PAUSE TestClientErrorHandling/ServerNotAvailable1428=== CONT TestService_AuthMiddleware_OIDC14292026/11/06 07:10:54 INFO Vacuumed table table=closures14302026/11/06 07:10:54 INFO Vacuumed table table=objects14312026/11/06 07:10:54 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53956/oidc14322026/11/06 07:10:54 INFO Aborted multipart uploads count=0 kept=014332026/11/06 07:10:54 WARN Force mode enabled - objects will be deleted immediately without grace period14342026/11/06 07:10:54 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=014352026/11/06 07:10:55 INFO Vacuumed table table=pending_closures14362026/11/06 07:10:55 INFO Vacuumed table table=pending_objects14372026/11/06 07:10:55 INFO Vacuumed table table=multipart_uploads14382026/11/06 07:10:55 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld2 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1439--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (8.85s)1440=== CONT TestClientCADerivations14412026/11/06 07:10:55 INFO Vacuumed table table=closures14422026/11/06 07:10:55 INFO Vacuumed table table=objects1443--- PASS: TestCommitRacingPendingCleanupKeepsObjects (10.09s)1444=== CONT TestCacheConfigHandler1445=== RUN TestCacheConfigHandler/full_config,_no_issuer1446=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1447=== RUN TestCacheConfigHandler/no_cache_url_configured1448=== PAUSE TestCacheConfigHandler/no_cache_url_configured1449=== RUN TestCacheConfigHandler/no_signing_keys1450=== PAUSE TestCacheConfigHandler/no_signing_keys1451=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1452=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1453=== CONT TestService_ReadScope_PublicByDefault14542026/11/06 07:10:55 INFO Received uploads request method=POST path=/api/pending_closures14552026/11/06 07:10:55 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=014562026/11/06 07:10:55 INFO Received create pin request method=POST path=/api/pins/myapp14572026/11/06 07:10:55 INFO Created/updated pin name=myapp store_path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestPinProtectsFromGC2938947068/001/store/vlkf076y8hm605x4bd0g15spmll9r7gc-pinned-file.txt narinfo_key=vlkf076y8hm605x4bd0g15spmll9r7gc.narinfo14582026/11/06 07:10:55 INFO Starting cleanup of old closures method=DELETE path=/api/closures14592026/11/06 07:10:55 INFO Garbage collection started14602026/11/06 07:10:55 INFO Aborted multipart uploads count=0 kept=014612026/11/06 07:10:55 WARN Force mode enabled - objects will be deleted immediately without grace period14622026/11/06 07:10:55 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=014632026/11/06 07:10:55 INFO Vacuumed table table=pending_closures14642026/11/06 07:10:55 INFO Vacuumed table table=pending_objects14652026/11/06 07:10:55 INFO Vacuumed table table=multipart_uploads14662026/11/06 07:10:55 INFO Vacuumed table table=closures14672026/11/06 07:10:56 INFO Vacuumed table table=objects1468--- PASS: TestPushWaitsForSweepHoldingRow (9.54s)1469=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14702026/11/06 07:10:56 INFO lead: acquired remote=192.0.2.1:123414712026/11/06 07:10:56 INFO Aborted multipart uploads count=0 kept=014722026/11/06 07:10:56 WARN Force mode enabled - objects will be deleted immediately without grace period14732026/11/06 07:10:56 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=014742026/11/06 07:10:57 INFO Vacuumed table table=pending_closures14752026/11/06 07:10:57 INFO Vacuumed table table=pending_objects14762026/11/06 07:10:57 INFO Vacuumed table table=multipart_uploads14772026/11/06 07:10:57 INFO Vacuumed table table=closures14782026/11/06 07:10:57 INFO Vacuumed table table=objects1479--- PASS: TestSweepRechecksPendingAfterLocking (9.01s)1480=== CONT TestService_RequireScope_OIDC14812026/11/06 07:10:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53968/oidc14822026/11/06 07:10:57 INFO lead: released remote=192.0.2.1:12341483--- PASS: TestLeadEndsOnShutdown (9.77s)1484=== CONT TestService_ReadAuthMiddleware1485--- PASS: TestGetExistingObjectsLocksRows (8.88s)1486=== CONT TestGCSweepDeliversEachKeyOnce14872026/11/06 07:10:57 INFO Received uploads request method=POST path=/api/pending_closures1488=== NAME TestPinProtectsFromGC1489 client_integration_test.go:887: Pin successfully protected closure from garbage collection14902026/11/06 07:10:58 INFO Received cleanup request method=DELETE path=/api/pending_closures14912026/11/06 07:10:58 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket66/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""14922026/11/06 07:10:58 INFO Aborted multipart uploads count=0 kept=114932026/11/06 07:10:58 INFO Aborted multipart uploads count=1 kept=014942026/11/06 07:10:58 INFO Received cleanup request method=DELETE path=/api/pending_closures14952026/11/06 07:10:58 INFO Aborted multipart uploads count=1 kept=01496--- PASS: TestMultipartCleanup (9.25s)14972026/11/06 07:10:58 INFO Received cleanup request method=DELETE path=/api/pending_closures1498=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1499--- PASS: TestPinProtectsFromGC (14.72s)1500=== CONT TestSweepSkipsRowsLockedByPush15012026/11/06 07:10:58 INFO Aborted multipart uploads count=1 kept=01502--- PASS: TestPendingCleanupUsesOneCutoff (16.59s)1503=== CONT TestForceGCDuringPushOffersSweptObject1504=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1505=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1506=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1507=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1508=== CONT TestTombstonedObjectOfferedWithoutWaiting15092026/11/06 07:10:58 INFO lead: acquired remote=192.0.2.1:12341510--- PASS: TestConnectWaitsForAPeerMigration (8.48s)1511=== CONT TestFailedS3DeleteKeepsTombstone15122026/11/06 07:10:58 INFO lead: acquired remote=192.0.2.1:123415132026/11/06 07:10:58 INFO lead: released remote=192.0.2.1:12341514--- PASS: TestLeadIncumbentAnnouncesAtOnce (10.01s)1515=== CONT TestService_AuthMiddleware_MTLSProxyHeader15162026/11/06 07:10:59 INFO lead: released remote=192.0.2.1:123415172026/11/06 07:10:59 INFO lead: acquired remote=192.0.2.1:123415182026/11/06 07:11:00 INFO lead: released remote=192.0.2.1:12341519--- PASS: TestLeadElectsOneAndHandsOver (11.33s)1520=== CONT TestIsValidCachePath/narinfo1521=== CONT TestIsValidCachePath/index.html1522=== CONT TestIsValidCachePath/short_hash1523=== CONT TestIsValidCachePath/wrong_extension1524=== CONT TestIsValidCachePath/leading_slash1525=== CONT TestIsValidCachePath/empty1526=== CONT TestIsValidCachePath/random_path1527=== CONT TestIsValidCachePath/invalid_char_u1528=== CONT TestIsValidCachePath/invalid_char_e1529=== CONT TestIsValidCachePath/traversal_in_middle1530=== CONT TestIsValidCachePath/traversal_parent1531=== CONT TestIsValidCachePath/nar_uncompressed1532=== CONT TestIsValidCachePath/nix-cache-info1533=== CONT TestIsValidCachePath/realisation1534=== CONT TestIsValidCachePath/log1535=== CONT TestIsValidCachePath/ls1536=== CONT TestIsValidCachePath/nar_xz1537=== CONT TestIsValidCachePath/nar_bz21538=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1539=== CONT TestIsValidCachePath/nar_zst1540=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1541--- PASS: TestIsValidCachePath (0.00s)1542 --- PASS: TestIsValidCachePath/narinfo (0.00s)1543 --- PASS: TestIsValidCachePath/index.html (0.00s)1544 --- PASS: TestIsValidCachePath/short_hash (0.00s)1545 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1546 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1547 --- PASS: TestIsValidCachePath/empty (0.00s)1548 --- PASS: TestIsValidCachePath/random_path (0.00s)1549 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1550 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1551 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1552 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1553 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1554 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1555 --- PASS: TestIsValidCachePath/realisation (0.00s)1556 --- PASS: TestIsValidCachePath/log (0.00s)1557 --- PASS: TestIsValidCachePath/ls (0.00s)1558 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1559 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1560 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1561 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1562--- PASS: TestCacheStatsHandler (9.93s)1563=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed1564--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (11.47s)1565=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed15662026/11/06 07:11:01 INFO Received uploads request method=POST path=/api/pending_closures15672026/11/06 07:11:02 INFO Received uploads request method=POST path=/api/pending_closures15682026/11/06 07:11:02 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15692026/11/06 07:11:02 INFO Uploading 8z6mwyj6a23rz66hy00wam25lwck4v9l-b (256B)15702026/11/06 07:11:02 INFO Uploading m2gpv6wy1rgql3m5a2jw2grx5l31ljn0-shared-dep (136B)15712026/11/06 07:11:02 WARN Failed to register uploaded object key=44qjmrdhykr2zv50xs8pyb054b241iw4.ls error="server returned 404: 404 page not found\n"15722026/11/06 07:11:02 WARN Failed to register uploaded object key=8z6mwyj6a23rz66hy00wam25lwck4v9l.ls error="server returned 404: 404 page not found\n"15732026/11/06 07:11:02 WARN Failed to register uploaded object key=m2gpv6wy1rgql3m5a2jw2grx5l31ljn0.ls error="server returned 404: 404 page not found\n"15742026/11/06 07:11:02 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15752026/11/06 07:11:02 WARN Failed to register uploaded object key=nar/1h1lpi9amxz757dkws2p8ldif92hkhif85b8wgy8ac3xkz82kgxm.nar.zst error="server returned 404: 404 page not found\n"15762026/11/06 07:11:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign15772026/11/06 07:11:02 INFO Signed narinfos id=1 count=215782026/11/06 07:11:02 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign15792026/11/06 07:11:02 INFO Signed narinfos id=2 count=215802026/11/06 07:11:02 INFO Uploading 4 narinfos15812026/11/06 07:11:02 WARN Failed to register uploaded object key=m2gpv6wy1rgql3m5a2jw2grx5l31ljn0.narinfo error="server returned 404: 404 page not found\n"15822026/11/06 07:11:02 WARN Failed to register uploaded object key=8z6mwyj6a23rz66hy00wam25lwck4v9l.narinfo error="server returned 404: 404 page not found\n"15832026/11/06 07:11:02 WARN Failed to register uploaded object key=44qjmrdhykr2zv50xs8pyb054b241iw4.narinfo error="server returned 404: 404 page not found\n"15842026/11/06 07:11:02 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete15852026/11/06 07:11:02 WARN Failed to register uploaded object key=m2gpv6wy1rgql3m5a2jw2grx5l31ljn0.narinfo error="server returned 404: 404 page not found\n"15862026/11/06 07:11:02 INFO Completed upload id=1 objects=6 duration=69.389625ms15872026/11/06 07:11:02 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete15882026/11/06 07:11:02 INFO Completed upload id=2 objects=6 duration=1.149292ms15892026/11/06 07:11:02 INFO Upload complete. (983ms)1590=== NAME TestClientFallsBackToClosures1591 client_pushes_test.go:112: Retrieved narinfo from S3:1592 StorePath: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientFallsBackToClosures3130772403/001/store/m2gpv6wy1rgql3m5a2jw2grx5l31ljn0-shared-dep1593 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1594 Compression: zstd1595 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821596 NarSize: 1361597 References: 1598 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1599 client_pushes_test.go:112: Retrieved narinfo from S3:1600 StorePath: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientFallsBackToClosures3130772403/001/store/44qjmrdhykr2zv50xs8pyb054b241iw4-a1601 URL: nar/1h1lpi9amxz757dkws2p8ldif92hkhif85b8wgy8ac3xkz82kgxm.nar.zst1602 Compression: zstd1603 NarHash: sha256:1h1lpi9amxz757dkws2p8ldif92hkhif85b8wgy8ac3xkz82kgxm1604 NarSize: 2561605 References: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientFallsBackToClosures3130772403/001/store/m2gpv6wy1rgql3m5a2jw2grx5l31ljn0-shared-dep1606 CA: text:sha256:09m8k90s3hsl8bhjw01dngj7cswqiydbdsixf9dvl49a3jr6kmcr1607 client_pushes_test.go:112: Retrieved narinfo from S3:1608 StorePath: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientFallsBackToClosures3130772403/001/store/8z6mwyj6a23rz66hy00wam25lwck4v9l-b1609 URL: nar/1h1lpi9amxz757dkws2p8ldif92hkhif85b8wgy8ac3xkz82kgxm.nar.zst1610 Compression: zstd1611 NarHash: sha256:1h1lpi9amxz757dkws2p8ldif92hkhif85b8wgy8ac3xkz82kgxm1612 NarSize: 2561613 References: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientFallsBackToClosures3130772403/001/store/m2gpv6wy1rgql3m5a2jw2grx5l31ljn0-shared-dep1614 CA: text:sha256:09m8k90s3hsl8bhjw01dngj7cswqiydbdsixf9dvl49a3jr6kmcr16152026/11/06 07:11:02 WARN mTLS auth: subject not in bound subjects subject="CN=reader"16162026/11/06 07:11:02 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1617--- PASS: TestService_NativeMTLS (10.60s)1618=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1619--- PASS: TestClientFallsBackToClosures (11.87s)1620=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed16212026/11/06 07:11:03 INFO Received push request method=POST path=/api/pushes16222026/11/06 07:11:03 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16232026/11/06 07:11:03 INFO Uploading sf61hfjijzk2rg5zpqvcw07niska7h3v-b (256B)16242026/11/06 07:11:03 INFO Uploading shd018k6si1xm4dm1bjhdyav4npa7gzl-shared-dep (136B)16252026/11/06 07:11:03 WARN Failed to register uploaded object key=17wigmsfzgj6fl1h4p3xwslsrdaq1bqn.ls error="server returned 404: 404 page not found\n"16262026/11/06 07:11:03 WARN Failed to register uploaded object key=nar/1lk73k4ah9az9yv73rjgadxq4yhfdnb84266h3g86j3a2sk6aqj4.nar.zst error="server returned 404: 404 page not found\n"16272026/11/06 07:11:03 WARN Failed to register uploaded object key=shd018k6si1xm4dm1bjhdyav4npa7gzl.ls error="server returned 404: 404 page not found\n"16282026/11/06 07:11:03 WARN Failed to register uploaded object key=sf61hfjijzk2rg5zpqvcw07niska7h3v.ls error="server returned 404: 404 page not found\n"16292026/11/06 07:11:03 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16302026/11/06 07:11:03 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16312026/11/06 07:11:03 INFO Signed narinfos id=1 count=316322026/11/06 07:11:03 INFO Uploading 3 narinfos16332026/11/06 07:11:03 WARN Failed to register uploaded object key=sf61hfjijzk2rg5zpqvcw07niska7h3v.narinfo error="server returned 404: 404 page not found\n"16342026/11/06 07:11:03 INFO Received complete push request method=POST path=/api/pushes/1/complete16352026/11/06 07:11:03 WARN Failed to register uploaded object key=17wigmsfzgj6fl1h4p3xwslsrdaq1bqn.narinfo error="server returned 404: 404 page not found\n"16362026/11/06 07:11:03 WARN Failed to register uploaded object key=shd018k6si1xm4dm1bjhdyav4npa7gzl.narinfo error="server returned 404: 404 page not found\n"16372026/11/06 07:11:03 INFO Completed push id=1 objects=8 duration=124.523291ms16382026/11/06 07:11:03 INFO Upload complete. (675ms)1639=== NAME TestClientPushesUseOnePush1640 client_pushes_test.go:97: Retrieved narinfo from S3:1641 StorePath: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientPushesUseOnePush1125915274/001/store/shd018k6si1xm4dm1bjhdyav4npa7gzl-shared-dep1642 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1643 Compression: zstd1644 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821645 NarSize: 1361646 References: 1647 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1648 client_pushes_test.go:97: Retrieved narinfo from S3:1649 StorePath: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientPushesUseOnePush1125915274/001/store/17wigmsfzgj6fl1h4p3xwslsrdaq1bqn-a1650 URL: nar/1lk73k4ah9az9yv73rjgadxq4yhfdnb84266h3g86j3a2sk6aqj4.nar.zst1651 Compression: zstd1652 NarHash: sha256:1lk73k4ah9az9yv73rjgadxq4yhfdnb84266h3g86j3a2sk6aqj41653 NarSize: 2561654 References: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientPushesUseOnePush1125915274/001/store/shd018k6si1xm4dm1bjhdyav4npa7gzl-shared-dep1655 CA: text:sha256:0i0knm2ck7zhl04bzcxbm6yfcggfararzs83wyac7hmszpkxiifr1656 client_pushes_test.go:97: Retrieved narinfo from S3:1657 StorePath: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientPushesUseOnePush1125915274/001/store/sf61hfjijzk2rg5zpqvcw07niska7h3v-b1658 URL: nar/1lk73k4ah9az9yv73rjgadxq4yhfdnb84266h3g86j3a2sk6aqj4.nar.zst1659 Compression: zstd1660 NarHash: sha256:1lk73k4ah9az9yv73rjgadxq4yhfdnb84266h3g86j3a2sk6aqj41661 NarSize: 2561662 References: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientPushesUseOnePush1125915274/001/store/shd018k6si1xm4dm1bjhdyav4npa7gzl-shared-dep1663 CA: text:sha256:0i0knm2ck7zhl04bzcxbm6yfcggfararzs83wyac7hmszpkxiifr1664--- PASS: TestClientPushesUseOnePush (12.25s)1665=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure16662026/11/06 07:11:03 INFO Received uploads request method=POST path=/16672026/11/06 07:11:05 INFO Received push request method=POST path=/api/pushes16682026/11/06 07:11:05 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16692026/11/06 07:11:05 INFO Uploading h3bq541mnzjkaf3h6jjbj16qv3dd13vd-shared-dep (136B)16702026/11/06 07:11:05 INFO Uploading irzvl0zwrhlzdqf13r6r2ap806mdvinq-top (264B)1671=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1672=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1673=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1674=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1675=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1676=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1677=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1678=== NAME TestClientMultipleUploads1679 client_integration_test.go:405: Created store path 0: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientMultipleUploads1379728646/001/store/71qs8ihmpzfm6lvm9imah8mhkkhhyjxz-test-file-0.txt1680=== NAME TestClientIntegration1681 client_integration_test.go:291: Created store path: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientIntegration713315321/002/store/j3lsk00j1w2ny6ngf4khrc7c8rbn26cg-test-file.txt1682=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1683=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info16842026/11/06 07:11:05 INFO Received uploads request method=POST path=/1685=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts16862026/11/06 07:11:05 INFO Received request for more parts method=POST path=/1687=== NAME TestClientWithDependencies1688 client_integration_test.go:660: Built derivation: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientWithDependencies2234125278/001/store/cvmxjlm73frry99ycskbg4xnzcy9np3m-test-script1689=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart16902026/11/06 07:11:05 INFO Received complete multipart upload request method=POST path=/1691=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key16922026/11/06 07:11:05 INFO Received complete multipart upload request method=POST path=/1693--- PASS: TestUploadHandlersRejectOversizedBody (0.31s)1694 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (2.01s)1695 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.20s)1696 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.05s)1697=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key16982026/11/06 07:11:05 WARN Failed to register uploaded object key=irzvl0zwrhlzdqf13r6r2ap806mdvinq.ls error="server returned 404: 404 page not found\n"1699=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17002026/11/06 07:11:05 INFO Received request for more parts method=POST path=/1701=== CONT TestIsValidUploadKey/narinfo17022026/11/06 07:11:05 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"1703=== CONT TestPendingClosureWriteTimeout/empty17042026/11/06 07:11:05 INFO Received uploads request method=POST path=/1705=== CONT TestIsValidUploadKey/unknown_type1706=== CONT TestIsValidUploadKey/empty_key1707=== CONT TestIsValidUploadKey/absolute1708=== CONT TestIsValidUploadKey/traversal_nar1709=== CONT TestIsValidUploadKey/traversal1710=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1711=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1712=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1713=== CONT TestIsValidUploadKey/index.html1714=== CONT TestIsValidUploadKey/nix-cache-info1715=== CONT TestIsValidUploadKey/realisation_plus_in_output1716=== CONT TestIsValidUploadKey/realisation1717=== CONT TestIsValidUploadKey/build_log_equals1718=== CONT TestIsValidUploadKey/build_log_question_mark1719=== CONT TestIsValidUploadKey/build_log_plus_in_name1720=== CONT TestIsValidUploadKey/build_log_home-manager_file1721=== CONT TestIsValidUploadKey/listing1722=== CONT TestIsValidUploadKey/nar_plain1723=== CONT TestIsValidUploadKey/nar_xz1724=== CONT TestIsValidUploadKey/nar_zst1725=== CONT TestPendingClosureWriteTimeout/670k_objects1726=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1727=== CONT TestIsValidUploadKey/build_log1728=== CONT TestPendingClosureWriteTimeout/400_objects1729=== CONT TestProxyWriteTimeout/narinfo1730=== CONT TestProxyWriteTimeout/10_GiB_nar1731=== CONT TestProxyWriteTimeout/unknown_size1732=== CONT TestProxyWriteTimeout/1_GiB_nar1733=== CONT TestParseSingleRange/none1734=== CONT TestParseSingleRange/open-ended1735=== CONT TestParseSingleRange/start_far_past_EOF1736=== CONT TestParseSingleRange/start_past_EOF1737=== CONT TestParseSingleRange/single_byte1738=== CONT TestParseSingleRange/suffix_exceeds_size1739=== CONT TestParseSingleRange/suffix1740=== CONT TestParseSingleRange/end_clamped_to_size1741=== CONT TestParseSingleRange/malformed_both_empty1742=== CONT TestParseSingleRange/closed1743=== CONT TestParseSingleRange/malformed_end_before_start1744=== CONT TestParseSingleRange/multi-range_ignored1745=== CONT TestParseSingleRange/malformed_no_dash1746=== CONT TestParseSingleRange/unknown_unit1747=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1748--- PASS: TestUploadHandlersRejectInvalidKeys (0.00s)1749 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.01s)1750 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.01s)1751 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.02s)1752 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.03s)1753--- PASS: TestIsValidUploadKey (0.00s)1754 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1755 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1756 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1757 --- PASS: TestIsValidUploadKey/absolute (0.00s)1758 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1759 --- PASS: TestIsValidUploadKey/traversal (0.00s)1760 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1761 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1762 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1763 --- PASS: TestIsValidUploadKey/index.html (0.00s)1764 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1765 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1766 --- PASS: TestIsValidUploadKey/realisation (0.00s)1767 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1768 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1769 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1770 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1771 --- PASS: TestIsValidUploadKey/listing (0.00s)1772 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1773 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1774 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1775 --- PASS: TestIsValidUploadKey/build_log (0.00s)17762026/11/06 07:11:05 WARN Failed to register uploaded object key=h3bq541mnzjkaf3h6jjbj16qv3dd13vd.ls error="server returned 404: 404 page not found\n"1777--- PASS: TestProxyWriteTimeout (0.00s)1778 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1779 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1780 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1781 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1782--- PASS: TestParseSingleRange (0.02s)1783 --- PASS: TestParseSingleRange/none (0.00s)1784 --- PASS: TestParseSingleRange/open-ended (0.00s)1785 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1786 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1787 --- PASS: TestParseSingleRange/single_byte (0.00s)1788 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1789 --- PASS: TestParseSingleRange/suffix (0.00s)1790 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1791 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1792 --- PASS: TestParseSingleRange/closed (0.00s)1793 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1794 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1795 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1796 --- PASS: TestParseSingleRange/unknown_unit (0.00s)17972026/11/06 07:11:05 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1798=== NAME TestClientMultipleUploads1799 client_integration_test.go:405: Created store path 1: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientMultipleUploads1379728646/001/store/h5m51hhbic096020j1lvp3q6lpb6s2c3-test-file-1.txt1800=== NAME TestClientWithDependencies1801 client_integration_test.go:662: Found 1 dependencies (including self)18022026/11/06 07:11:05 INFO Signed narinfos id=1 count=218032026/11/06 07:11:05 WARN Failed to register uploaded object key=nar/0ndwhkl7663jsj0ghk24s9v6blvvx1spprvyhvkhbg1bhfj0qiq5.nar.zst error="server returned 404: 404 page not found\n"18042026/11/06 07:11:05 INFO Uploading 2 narinfos18052026/11/06 07:11:06 INFO Received complete push request method=POST path=/api/pushes/1/complete18062026/11/06 07:11:06 WARN Failed to register uploaded object key=irzvl0zwrhlzdqf13r6r2ap806mdvinq.narinfo error="server returned 404: 404 page not found\n"18072026/11/06 07:11:06 WARN Failed to register uploaded object key=h3bq541mnzjkaf3h6jjbj16qv3dd13vd.narinfo error="server returned 404: 404 page not found\n"18082026/11/06 07:11:06 INFO Received push request method=POST path=/api/pushes18092026/11/06 07:11:06 INFO Completed push id=1 objects=6 duration=60.663708ms1810=== NAME TestClientMultipleUploads1811 client_integration_test.go:405: Created store path 2: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientMultipleUploads1379728646/001/store/0f07dn1xmkhc6y7735xxjfghd1wd5ck0-test-file-2.txt18122026/11/06 07:11:06 INFO Upload complete. (1.705s)1813=== NAME TestClientSharedPathCommittedMidPush1814 client_integration_test.go:727: Retrieved narinfo from S3:1815 StorePath: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientSharedPathCommittedMidPush1987563859/001/store/h3bq541mnzjkaf3h6jjbj16qv3dd13vd-shared-dep1816 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1817 Compression: zstd1818 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821819 NarSize: 1361820 References: 1821 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n18222026/11/06 07:11:06 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18232026/11/06 07:11:06 INFO Uploading j3lsk00j1w2ny6ngf4khrc7c8rbn26cg-test-file.txt (152B)1824 client_integration_test.go:727: Retrieved narinfo from S3:1825 StorePath: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientSharedPathCommittedMidPush1987563859/001/store/irzvl0zwrhlzdqf13r6r2ap806mdvinq-top1826 URL: nar/0ndwhkl7663jsj0ghk24s9v6blvvx1spprvyhvkhbg1bhfj0qiq5.nar.zst1827 Compression: zstd1828 NarHash: sha256:0ndwhkl7663jsj0ghk24s9v6blvvx1spprvyhvkhbg1bhfj0qiq51829 NarSize: 2641830 References: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientSharedPathCommittedMidPush1987563859/001/store/h3bq541mnzjkaf3h6jjbj16qv3dd13vd-shared-dep1831 CA: text:sha256:0ki1817g2m2dqpwrp971z30dgkay4f2mk199wm067pgrsbrzwbxj1832--- PASS: TestClientSharedPathCommittedMidPush (13.66s)1833=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh18342026/11/06 07:11:06 WARN Failed to register uploaded object key=j3lsk00j1w2ny6ngf4khrc7c8rbn26cg.ls error="server returned 404: 404 page not found\n"18352026/11/06 07:11:06 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18362026/11/06 07:11:06 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18372026/11/06 07:11:06 INFO Signed narinfos id=1 count=118382026/11/06 07:11:06 INFO Uploading 1 narinfos18392026/11/06 07:11:06 INFO Received push request method=POST path=/api/pushes18402026/11/06 07:11:06 INFO Received complete push request method=POST path=/api/pushes/1/complete18412026/11/06 07:11:06 WARN Failed to register uploaded object key=j3lsk00j1w2ny6ngf4khrc7c8rbn26cg.narinfo error="server returned 404: 404 page not found\n"18422026/11/06 07:11:06 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18432026/11/06 07:11:06 INFO Uploading cvmxjlm73frry99ycskbg4xnzcy9np3m-test-script (136B)18442026/11/06 07:11:06 INFO Completed push id=1 objects=3 duration=49.158833ms18452026/11/06 07:11:06 INFO Upload complete. (639ms)18462026/11/06 07:11:06 INFO Received push request method=POST path=/api/pushes18472026/11/06 07:11:06 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"18482026/11/06 07:11:06 WARN Failed to register uploaded object key=cvmxjlm73frry99ycskbg4xnzcy9np3m.ls error="server returned 404: 404 page not found\n"18492026/11/06 07:11:06 INFO All 1 paths already cached1850=== NAME TestClientIntegration1851 client_integration_test.go:317: Retrieved narinfo from S3:1852 StorePath: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientIntegration713315321/002/store/j3lsk00j1w2ny6ngf4khrc7c8rbn26cg-test-file.txt18532026/11/06 07:11:06 WARN Failed to register uploaded object key=log/b749i58zj0672jska0n3gmxg02dgi9dw-test-script.drv error="server returned 404: 404 page not found\n"1854 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst18552026/11/06 07:11:06 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)1856 Compression: zstd18572026/11/06 07:11:06 INFO Uploading 71qs8ihmpzfm6lvm9imah8mhkkhhyjxz-test-file-0.txt (160B)1858 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11859 NarSize: 1521860 References: 18612026/11/06 07:11:06 INFO Uploading 0f07dn1xmkhc6y7735xxjfghd1wd5ck0-test-file-2.txt (160B)1862 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk118632026/11/06 07:11:06 INFO Uploading h5m51hhbic096020j1lvp3q6lpb6s2c3-test-file-1.txt (160B)18642026/11/06 07:11:06 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18652026/11/06 07:11:06 INFO Signed narinfos id=1 count=11866 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1867 client_integration_test.go:318: Decompressed .ls content (64 bytes):18682026/11/06 07:11:06 INFO Uploading 1 narinfos1869 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}18702026/11/06 07:11:06 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18712026/11/06 07:11:06 WARN Failed to register uploaded object key=71qs8ihmpzfm6lvm9imah8mhkkhhyjxz.ls error="server returned 404: 404 page not found\n"18722026/11/06 07:11:06 WARN Failed to register uploaded object key=0f07dn1xmkhc6y7735xxjfghd1wd5ck0.ls error="server returned 404: 404 page not found\n"18732026/11/06 07:11:06 WARN Failed to register uploaded object key=h5m51hhbic096020j1lvp3q6lpb6s2c3.ls error="server returned 404: 404 page not found\n"18742026/11/06 07:11:06 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18752026/11/06 07:11:06 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18762026/11/06 07:11:06 INFO Received complete push request method=POST path=/api/pushes/1/complete18772026/11/06 07:11:06 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18782026/11/06 07:11:06 WARN Failed to register uploaded object key=cvmxjlm73frry99ycskbg4xnzcy9np3m.narinfo error="server returned 404: 404 page not found\n"18792026/11/06 07:11:06 INFO Signed narinfos id=1 count=318802026/11/06 07:11:06 INFO Uploading 3 narinfos18812026/11/06 07:11:06 INFO Completed push id=1 objects=4 duration=57.328667ms18822026/11/06 07:11:06 INFO Upload complete. (656ms)1883=== NAME TestClientWithDependencies18842026/11/06 07:11:06 WARN Failed to register uploaded object key=h5m51hhbic096020j1lvp3q6lpb6s2c3.narinfo error="server returned 404: 404 page not found\n"1885 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientWithDependencies2234125278/001/store) requires matching store prefix18862026/11/06 07:11:06 WARN Failed to register uploaded object key=0f07dn1xmkhc6y7735xxjfghd1wd5ck0.narinfo error="server returned 404: 404 page not found\n"18872026/11/06 07:11:06 INFO Received complete push request method=POST path=/api/pushes/1/complete18882026/11/06 07:11:06 WARN Failed to register uploaded object key=71qs8ihmpzfm6lvm9imah8mhkkhhyjxz.narinfo error="server returned 404: 404 page not found\n"1889--- PASS: TestService_ReadScope_PublicByDefault (11.54s)1890=== CONT TestPush_RejectsBadRequests/no_objects18912026/11/06 07:11:06 INFO Received push request method=POST path=/api/pushes18922026/11/06 07:11:06 INFO Completed push id=1 objects=9 duration=39.036084ms1893=== CONT TestPush_RejectsBadRequests/root_not_in_objects18942026/11/06 07:11:06 INFO Received push request method=POST path=/api/pushes1895=== CONT TestPush_RejectsBadRequests/no_roots18962026/11/06 07:11:06 INFO Received push request method=POST path=/api/pushes1897=== CONT TestPush_RejectsBadRequests/bad_root18982026/11/06 07:11:06 INFO Received push request method=POST path=/api/pushes1899=== CONT TestGCEndsOnShutdown/before_the_run1900--- PASS: TestPush_RejectsBadRequests (9.23s)1901 --- PASS: TestPush_RejectsBadRequests/no_objects (0.01s)1902 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1903 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1904 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)19052026/11/06 07:11:06 INFO Upload complete. (545ms)1906=== NAME TestClientMultipleUploads1907 client_integration_test.go:416: Uploaded 3 paths in 710.517ms1908--- PASS: TestClientWithDependencies (13.80s)1909=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1910--- PASS: TestClientMultipleUploads (13.04s)1911=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete19122026/11/06 07:11:07 INFO Received push request method=POST path=/api/pushes19132026/11/06 07:11:07 INFO Object in database but missing from S3 key=j3lsk00j1w2ny6ngf4khrc7c8rbn26cg.ls19142026/11/06 07:11:07 WARN Found objects in DB but missing from S3, will re-upload count=119152026/11/06 07:11:07 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19162026/11/06 07:11:07 INFO Received complete push request method=POST path=/api/pushes/2/complete19172026/11/06 07:11:07 WARN Failed to register uploaded object key=j3lsk00j1w2ny6ngf4khrc7c8rbn26cg.ls error="server returned 404: 404 page not found\n"19182026/11/06 07:11:07 INFO Completed push id=2 objects=3 duration=3.929667ms19192026/11/06 07:11:07 INFO Upload complete. (346ms)1920=== NAME TestClientIntegration1921 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1922 client_integration_test.go:335: Decompressed .ls content (49 bytes):1923 {"version":1,"root":{"type":"regular","size":39}}1924=== NAME TestClientCADerivations1925 client_ca_test.go:136: Built CA derivation: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientCADerivations2500644185/001/store/w5v3k6fm12qzs5fgg9h1x35ywgg1xp3f-ca-test19262026/11/06 07:11:07 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"19272026/11/06 07:11:07 WARN mTLS auth: bound subjects configured but subject DN unavailable19282026/11/06 07:11:07 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1929--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (11.24s)1930=== CONT TestServerTLSConfig/no_client_CA1931=== CONT TestServerTLSConfig/not_a_PEM_file1932=== CONT TestServerTLSConfig/missing_CA_file1933--- PASS: TestServerTLSConfig (0.01s)1934 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1935 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.02s)1936 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1937=== CONT TestResolveDBConnectionString/flag_wins1938=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1939=== CONT TestResolveDBConnectionString/missing_file_is_an_error1940=== CONT TestResolveDBConnectionString/file_when_flag_empty1941=== CONT TestResolveDBConnectionString/nothing_configured1942=== CONT TestClientErrorHandling/InvalidStorePath1943--- PASS: TestResolveDBConnectionString (0.06s)1944 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1945 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1946 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1947 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1948 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1949=== NAME TestClientCADerivations1950 client_ca_test.go:139: Found 1 dependencies (including self)1951--- PASS: TestDeleteClosuresRacingPins (17.09s)1952=== CONT TestClientErrorHandling/ServerNotAvailable19532026/11/06 07:11:08 INFO Received push request method=POST path=/api/pushes19542026/11/06 07:11:08 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19552026/11/06 07:11:08 INFO Received push request method=POST path=/api/pushes19562026/11/06 07:11:08 INFO Received complete push request method=POST path=/api/pushes/3/complete19572026/11/06 07:11:08 WARN Failed to register uploaded object key=j3lsk00j1w2ny6ngf4khrc7c8rbn26cg.ls error="server returned 404: 404 page not found\n"19582026/11/06 07:11:08 INFO Completed push id=3 objects=3 duration=3.6025ms19592026/11/06 07:11:08 INFO Upload complete. (327ms)19602026/11/06 07:11:08 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)1961=== NAME TestClientIntegration1962 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)19632026/11/06 07:11:08 INFO Uploading w5v3k6fm12qzs5fgg9h1x35ywgg1xp3f-ca-test (144B)1964 client_integration_test.go:352: Decompressed .ls content (49 bytes):1965 {"version":1,"root":{"type":"regular","size":39}}1966 client_integration_test.go:363: Testing garbage collection...19672026/11/06 07:11:08 INFO Aborted multipart uploads count=0 kept=019682026/11/06 07:11:08 WARN Failed to register uploaded object key=w5v3k6fm12qzs5fgg9h1x35ywgg1xp3f.ls error="server returned 404: 404 page not found\n"19692026/11/06 07:11:08 INFO Starting cleanup of old closures method=DELETE path=/api/closures19702026/11/06 07:11:08 INFO Garbage collection started19712026/11/06 07:11:08 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19722026/11/06 07:11:08 WARN Force mode enabled - objects will be deleted immediately without grace period19732026/11/06 07:11:08 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19742026/11/06 07:11:08 WARN Failed to register uploaded object key=log/hcncjhvzm3pnd91if3n0bwj5xhiiy0pz-ca-test.drv error="server returned 404: 404 page not found\n"19752026/11/06 07:11:08 INFO Signed narinfos id=1 count=119762026/11/06 07:11:08 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/present19772026/11/06 07:11:08 INFO Uploading 1 narinfos19782026/11/06 07:11:08 INFO Aborted multipart uploads count=0 kept=019792026/11/06 07:11:08 WARN Force mode enabled - objects will be deleted immediately without grace period1980=== RUN TestService_RequireScope_OIDC/builder_may_write1981=== PAUSE TestService_RequireScope_OIDC/builder_may_write1982=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1983=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1984=== RUN TestService_RequireScope_OIDC/ops_may_admin1985=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1986=== RUN TestService_RequireScope_OIDC/ops_may_not_write1987=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write19882026/11/06 07:11:08 INFO Received complete push request method=POST path=/api/pushes/1/complete1989=== RUN TestService_RequireScope_OIDC/reader_may_not_write19902026/11/06 07:11:08 WARN Failed to register uploaded object key=w5v3k6fm12qzs5fgg9h1x35ywgg1xp3f.narinfo error="server returned 404: 404 page not found\n"1991=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write19922026/11/06 07:11:08 WARN Request failed, retrying attempt=2 backoff=190.47291ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1993=== RUN TestService_RequireScope_OIDC/static_token_may_admin1994=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1995=== RUN TestService_RequireScope_OIDC/static_token_may_write1996=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1997=== RUN TestService_RequireScope_OIDC/reader_may_read1998=== PAUSE TestService_RequireScope_OIDC/reader_may_read1999=== RUN TestService_RequireScope_OIDC/writer_implies_read2000=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2001=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2002=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2003=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc2004=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc2005=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc20062026/11/06 07:11:08 INFO Completed push id=1 objects=4 duration=91.230959ms2007=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2008=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2009=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2010=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2011=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2012=== CONT TestClientErrorHandling/InvalidAuthToken20132026/11/06 07:11:08 INFO Upload complete. (1.037s)2014=== NAME TestClientCADerivations2015 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientCADerivations2500644185/001/store/w5v3k6fm12qzs5fgg9h1x35ywgg1xp3f-ca-test2016 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2017 Compression: zstd2018 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2019 NarSize: 1442020 References: 2021 Deriver: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientCADerivations2500644185/001/store/hcncjhvzm3pnd91if3n0bwj5xhiiy0pz-ca-test.drv2022 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2023 client_ca_test.go:185: Checking for realisation files in S3...2024 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2025 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache2026=== NAME TestOrphanedObjectsGCStressTest2027 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains20282026/11/06 07:11:08 WARN Request failed, retrying attempt=3 backoff=380.17801ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2029 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion2030=== NAME TestClientCADerivations2031 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket80?endpoint=http://localhost:53617®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/2/scratch/da980f7a6ee70515/build/TestClientCADerivations2500644185/001/store'2032 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 12033--- PASS: TestService_ReadAuthMiddleware (11.98s)2034=== CONT TestCacheConfigHandler/full_config,_no_issuer2035=== CONT TestCacheConfigHandler/no_signing_keys2036=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2037=== CONT TestCacheConfigHandler/no_cache_url_configured2038--- PASS: TestCacheConfigHandler (0.00s)2039 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2040 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2041 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2042 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2043=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows20442026/11/06 07:11:09 WARN Request failed, retrying attempt=4 backoff=754.392602ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20452026/11/06 07:11:09 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=020462026/11/06 07:11:09 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=02047--- PASS: TestClientCADerivations (14.10s)2048=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check20492026/11/06 07:11:09 INFO Vacuumed table table=pending_closures20502026/11/06 07:11:09 INFO Vacuumed table table=pending_objects20512026/11/06 07:11:09 INFO Vacuumed table table=multipart_uploads20522026/11/06 07:11:09 INFO Vacuumed table table=closures20532026/11/06 07:11:09 INFO Vacuumed table table=pending_closures20542026/11/06 07:11:09 INFO Vacuumed table table=objects20552026/11/06 07:11:09 INFO Vacuumed table table=pending_objects2056--- PASS: TestGCSweepDeliversEachKeyOnce (12.06s)2057=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token20582026/11/06 07:11:09 INFO Vacuumed table table=multipart_uploads2059=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2060=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20612026/11/06 07:11:09 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]2062=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20632026/11/06 07:11:09 WARN Authentication failed token_preview=eyJhbGciOi...3tk7zl_mPA token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2064=== CONT TestService_RequireScope_OIDC/builder_may_write2065=== CONT TestService_RequireScope_OIDC/reader_may_read2066=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2067=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2068--- PASS: TestService_AuthMiddleware_OIDC (11.06s)2069 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2070 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2071 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2072 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)20732026/11/06 07:11:09 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]2074=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2075=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2076=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2077=== CONT TestService_RequireScope_OIDC/writer_implies_read2078=== CONT TestService_RequireScope_OIDC/reader_may_not_write2079=== CONT TestService_RequireScope_OIDC/static_token_may_write2080=== CONT TestService_RequireScope_OIDC/static_token_may_admin2081=== CONT TestService_RequireScope_OIDC/ops_may_admin20822026/11/06 07:11:09 INFO Vacuumed table table=closures2083=== CONT TestService_RequireScope_OIDC/ops_may_not_write2084=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2085--- PASS: TestService_RequireScope_OIDC (11.63s)2086 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2087 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2088 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2089 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2090 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2091 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2092 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2093 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2094 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2095 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2096 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2097 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2098 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2099 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)21002026/11/06 07:11:09 INFO Vacuumed table table=objects21012026/11/06 07:11:09 INFO Received uploads request method=POST path=/api/pending_closures2102--- PASS: TestTombstonedObjectOfferedWithoutWaiting (11.33s)21032026/11/06 07:11:09 INFO Received uploads request method=POST path=/api/pending_closures21042026/11/06 07:11:10 WARN Request failed, retrying attempt=5 backoff=1.726193296s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2105--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (12.03s)21062026/11/06 07:11:10 INFO Aborted multipart uploads count=0 kept=021072026/11/06 07:11:10 WARN Force mode enabled - objects will be deleted immediately without grace period21082026/11/06 07:11:10 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=021092026/11/06 07:11:10 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=021102026/11/06 07:11:10 INFO Vacuumed table table=pending_closures2111=== NAME TestClientIntegration2112 client_integration_test.go:370: Objects in database after GC:21132026/11/06 07:11:10 INFO Vacuumed table table=pending_objects21142026/11/06 07:11:10 INFO Vacuumed table table=multipart_uploads2115 client_integration_test.go:370: Successfully deleted all objects with GC --force21162026/11/06 07:11:10 INFO Vacuumed table table=closures21172026/11/06 07:11:10 INFO Vacuumed table table=objects21182026/11/06 07:11:10 INFO Aborted multipart uploads count=0 kept=02119--- PASS: TestClientIntegration (16.30s)21202026/11/06 07:11:10 INFO Received uploads request method=POST path=/api/pending_closures21212026/11/06 07:11:10 WARN Force mode enabled - objects will be deleted immediately without grace period21222026/11/06 07:11:10 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=021232026/11/06 07:11:10 INFO Vacuumed table table=pending_closures21242026/11/06 07:11:10 INFO Vacuumed table table=pending_objects21252026/11/06 07:11:10 INFO Vacuumed table table=multipart_uploads21262026/11/06 07:11:10 INFO Vacuumed table table=closures21272026/11/06 07:11:10 INFO Vacuumed table table=objects2128--- PASS: TestSweepSkipsRowsLockedByPush (12.71s)21292026/11/06 07:11:10 INFO Aborted multipart uploads count=0 kept=02130--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (11.99s)21312026/11/06 07:11:10 WARN Force mode enabled - objects will be deleted immediately without grace period21322026/11/06 07:11:10 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."21332026/11/06 07:11:10 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."2134--- PASS: TestFailedS3DeleteKeepsTombstone (12.36s)21352026/11/06 07:11:11 INFO Received uploads request method=POST path=/api/pending_closures21362026/11/06 07:11:11 INFO Received uploads request method=POST path=/api/pending_closures21372026/11/06 07:11:11 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-config21382026/11/06 07:11:11 INFO Received uploads request method=POST path=/api/pending_closures21392026/11/06 07:11:11 WARN Request failed, retrying attempt=2 backoff=199.588014ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21402026/11/06 07:11:12 WARN Request failed, retrying attempt=3 backoff=384.977035ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21412026/11/06 07:11:12 INFO Received uploads request method=POST path=/api/pending_closures21422026/11/06 07:11:12 WARN Request failed, retrying attempt=4 backoff=784.422749ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21432026/11/06 07:11:12 INFO Received uploads request method=POST path=/api/pending_closures21442026/11/06 07:11:13 WARN Request failed, retrying attempt=5 backoff=1.62201541s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21452026/11/06 07:11:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21462026/11/06 07:11:13 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LjIzYzAyOGFkLTJkY2EtNGRiZS1hY2I0LThhNzkzOTg1ZWYzNHgxNzkzOTQ5MDcxMzAzMzA3MDAw parts=1021472026/11/06 07:11:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21482026/11/06 07:11:13 INFO Completed upload id=1 objects=3 duration=16.22225ms21492026/11/06 07:11:13 INFO Received uploads request method=POST path=/api/pending_closures21502026/11/06 07:11:13 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21512026/11/06 07:11:13 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LmYyOTQ4OTg5LTU4ZjctNDc0My04OWQ0LWMwNzJkNThmOWViN3gxNzkzOTQ5MDcxNjIwODUwMDAw parts=1021522026/11/06 07:11:13 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21532026/11/06 07:11:13 INFO Completed upload id=1 objects=3 duration=13.381833ms21542026/11/06 07:11:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21552026/11/06 07:11:14 INFO Received uploads request method=POST path=/api/pending_closures21562026/11/06 07:11:14 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21572026/11/06 07:11:14 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21582026/11/06 07:11:14 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LmFiMWUwZDRmLWU2NjItNDJjOS1hNDY0LTdmZDY0NjZkMzdmMngxNzkzOTQ5MDcxOTMxMzc1MDAw parts=1021592026/11/06 07:11:14 INFO Aborted multipart uploads count=0 kept=021602026/11/06 07:11:14 WARN Force mode enabled - objects will be deleted immediately without grace period21612026-11-06 07:11:14.172 UTC [84628] ERROR: canceling statement due to user request21622026-11-06 07:11:14.172 UTC [84628] STATEMENT: -- name: MarkStaleObjects :execrows2163 WITH RECURSIVE ct AS (2164 SELECT timezone('UTC', now()) AS now2165 ),2166 closure_reach AS (2167 -- Start with all closure keys2168 SELECT o.key, o.refs2169 FROM objects o2170 INNER JOIN closures c ON o.key = c.key2171 UNION2172 -- Recursively add all referenced objects2173 SELECT o.key, o.refs2174 FROM objects o2175 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2176 ),2177 reachable_objects AS (2178 SELECT DISTINCT key FROM closure_reach2179 ),2180 stale_objects AS (2181 SELECT o.key2182 FROM objects AS o, ct2183 WHERE2184 NOT EXISTS (2185 SELECT 12186 FROM reachable_objects ro2187 WHERE ro.key = o.key2188 )2189 AND NOT EXISTS (2190 SELECT 12191 FROM pending_objects AS po2192 WHERE po.key = o.key2193 )2194 AND o.deleted_at IS NULL -- Only mark fresh objects2195 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2196 FOR UPDATE2197 )2198 UPDATE objects2199 SET2200 deleted_at = ct.now,2201 first_deleted_at = COALESCE(first_deleted_at, ct.now)2202 FROM stale_objects, ct2203 WHERE objects.key = stale_objects.key2204 22052026/11/06 07:11:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22062026/11/06 07:11:14 INFO Completed upload id=1 objects=3 duration=21.426417ms22072026/11/06 07:11:14 INFO Received uploads request method=POST path=/api/pending_closures2208--- PASS: TestPendingClosureWriteTimeout (0.00s)2209 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2210 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2211 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2212 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (8.55s)22132026/11/06 07:11:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22142026/11/06 07:11:14 INFO Received uploads request method=POST path=/api/pending_closures22152026/11/06 07:11:14 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22162026/11/06 07:11:14 WARN Found objects in DB but missing from S3, will re-upload count=122172026/11/06 07:11:14 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LjFlOTM2MjdiLTY0NDUtNGQzMy1iMGJjLWE4MWQ5NWYwNWU2Y3gxNzkzOTQ5MDcyMzQwNzYwMDAw parts=1022182026/11/06 07:11:14 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22192026/11/06 07:11:14 INFO Completed upload id=1 objects=3 duration=17.317458ms22202026/11/06 07:11:14 INFO Received uploads request method=POST path=/api/pending_closures22212026/11/06 07:11:14 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22222026/11/06 07:11:14 INFO Aborted multipart uploads count=0 kept=022232026/11/06 07:11:14 WARN Force mode enabled - objects will be deleted immediately without grace period22242026/11/06 07:11:14 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"22252026/11/06 07:11:14 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-config22262026/11/06 07:11:14 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:53617/bucket100/?delete=\": context canceled"2227--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2228 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (7.83s)2229 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (8.82s)22302026/11/06 07:11:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LmJmOGYzZjk3LWMyYjctNGM1Zi1hNjU3LWM5NjAxNGQ0ZTlmZngxNzkzOTQ5MDcyNzY2OTIzMDAw parts=1022312026/11/06 07:11:15 WARN Request failed, retrying attempt=2 backoff=203.116374ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22322026/11/06 07:11:15 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22332026/11/06 07:11:15 INFO Completed upload id=1 objects=3 duration=17.682834ms22342026/11/06 07:11:15 INFO Received uploads request method=POST path=/api/pending_closures22352026/11/06 07:11:15 WARN Request failed, retrying attempt=3 backoff=361.59283ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2236--- PASS: TestGCEndsOnShutdown (0.01s)2237 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (7.33s)2238 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (8.01s)2239 --- PASS: TestGCEndsOnShutdown/before_the_run (8.47s)22402026/11/06 07:11:15 WARN Request failed, retrying attempt=4 backoff=785.637788ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22412026/11/06 07:11:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22422026/11/06 07:11:15 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LjYzODRlN2ZmLTk4OWUtNGYwYy05NjY4LWFlMTgwNWYyNjZjNHgxNzkzOTQ5MDc0MjY0NTM0MDAw parts=1022432026/11/06 07:11:15 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22442026/11/06 07:11:15 INFO Completed upload id=2 objects=3 duration=463.042µs22452026/11/06 07:11:16 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22462026/11/06 07:11:16 INFO Received uploads request method=POST path=/api/pending_closures22472026/11/06 07:11:16 INFO Aborted multipart uploads count=0 kept=022482026/11/06 07:11:16 WARN Force mode enabled - objects will be deleted immediately without grace period22492026/11/06 07:11:16 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22502026/11/06 07:11:16 INFO Received uploads request method=POST path=/api/pending_closures22512026/11/06 07:11:16 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22522026/11/06 07:11:16 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22532026/11/06 07:11:16 WARN Request failed, retrying attempt=5 backoff=1.675308158s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22542026/11/06 07:11:16 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=022552026/11/06 07:11:16 INFO Vacuumed table table=pending_closures22562026/11/06 07:11:16 INFO Vacuumed table table=pending_objects22572026/11/06 07:11:16 INFO Vacuumed table table=multipart_uploads22582026/11/06 07:11:16 INFO Vacuumed table table=closures22592026/11/06 07:11:16 INFO Received uploads request method=POST path=/api/pending_closures22602026/11/06 07:11:16 INFO Vacuumed table table=objects22612026/11/06 07:11:16 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22622026/11/06 07:11:16 INFO Aborted multipart uploads count=0 kept=022632026/11/06 07:11:16 WARN Force mode enabled - objects will be deleted immediately without grace period22642026/11/06 07:11:16 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=022652026/11/06 07:11:16 INFO Vacuumed table table=pending_closures22662026/11/06 07:11:16 INFO Vacuumed table table=pending_objects22672026/11/06 07:11:16 INFO Vacuumed table table=multipart_uploads22682026/11/06 07:11:16 INFO Vacuumed table table=closures22692026/11/06 07:11:16 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=NTJhNjQ5MDctMTk3ZC00YTQxLWE3YmMtNWQwYzYxODJjYzc2LjIxYmU0ZjhjLTMxZDYtNDhjYy04OTgyLWVjYTY0MDdkYTZlZXgxNzkzOTQ5MDc1MDk4NTU2MDAw parts=1022702026/11/06 07:11:16 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22712026/11/06 07:11:16 INFO Completed upload id=2 objects=3 duration=635.417µs22722026/11/06 07:11:16 INFO Vacuumed table table=objects2273--- PASS: TestForceGCDuringPushOffersSweptObject (0.05s)2274 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (7.52s)2275 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (7.52s)22762026/11/06 07:11:17 INFO Received uploads request method=POST path=/api/pending_closures22772026/11/06 07:11:17 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22782026/11/06 07:11:17 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2279--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.00s)2280 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (13.28s)2281 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (12.59s)2282 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (11.75s)2283 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (14.78s)2284 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (14.14s)22852026/11/06 07:11:18 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_closures22862026/11/06 07:11:18 WARN Request failed, retrying attempt=2 backoff=203.554842ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22872026/11/06 07:11:18 WARN Request failed, retrying attempt=3 backoff=401.921369ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22882026/11/06 07:11:18 WARN Request failed, retrying attempt=4 backoff=797.236071ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22892026/11/06 07:11:19 WARN Request failed, retrying attempt=5 backoff=1.714032926s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2290--- PASS: TestClientErrorHandling (0.00s)2291 --- PASS: TestClientErrorHandling/InvalidStorePath (8.17s)2292 --- PASS: TestClientErrorHandling/InvalidAuthToken (7.67s)2293 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.59s)2294=== NAME TestOrphanedObjectsGCStressTest2295 orphaned_objects_gc_test.go:503: Stress test completed successfully:2296 orphaned_objects_gc_test.go:504: - Active objects preserved: 202297 orphaned_objects_gc_test.go:505: - Objects deleted: 2102298 orphaned_objects_gc_test.go:506: - Total GC'd: 2102299--- PASS: TestOrphanedObjectsGCStressTest (47.24s)2300PASS2301{"timestamp":"2026-11-06T07:11:26.615219Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54121","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)"}2302{"timestamp":"2026-11-06T07:11:26.615852Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53889","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)"}2303{"timestamp":"2026-11-06T07:11:26.615863Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54264","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(6)"}2304{"timestamp":"2026-11-06T07:11:26.615865Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54226","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(4)"}2305{"timestamp":"2026-11-06T07:11:26.616264Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:54263","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)"}23062026-11-06 07:11:26.794 UTC [80988] LOG: received smart shutdown request23072026-11-06 07:11:26.797 UTC [80988] LOG: background worker "logical replication launcher" (PID 81011) exited with exit code 123082026-11-06 07:11:26.821 UTC [81001] LOG: shutting down23092026-11-06 07:11:26.822 UTC [81001] LOG: checkpoint starting: shutdown immediate23102026-11-06 07:11:28.775 UTC [81001] LOG: checkpoint complete: wrote 11472 buffers (70.0%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=1.092 s, sync=0.790 s, total=1.954 s; sync files=35730, longest=0.014 s, average=0.001 s; distance=525341 kB, estimate=525341 kB; lsn=0/218944E0, redo lsn=0/218944E023112026-11-06 07:11:28.787 UTC [80988] LOG: database system is shut down2312Running OIDC tests...2313=== RUN TestAudienceForIssuer2314=== PAUSE TestAudienceForIssuer2315=== RUN TestGlobMatch2316=== PAUSE TestGlobMatch2317=== RUN TestValidateToken_ValidToken2318=== PAUSE TestValidateToken_ValidToken2319=== RUN TestValidateToken_WrongAudience2320=== PAUSE TestValidateToken_WrongAudience2321=== RUN TestValidateToken_Expired2322=== PAUSE TestValidateToken_Expired2323=== RUN TestValidateToken_BoundClaimsMismatch2324=== PAUSE TestValidateToken_BoundClaimsMismatch2325=== RUN TestValidateToken_BoundSubjectMismatch2326=== PAUSE TestValidateToken_BoundSubjectMismatch2327=== RUN TestValidateToken_MultipleProviders2328=== PAUSE TestValidateToken_MultipleProviders2329=== RUN TestValidateToken_NoMatchingProvider2330=== PAUSE TestValidateToken_NoMatchingProvider2331=== RUN TestValidateToken_KubernetesServiceAccount2332=== PAUSE TestValidateToken_KubernetesServiceAccount2333=== RUN TestNewValidator_KubernetesRequiresCA2334=== PAUSE TestNewValidator_KubernetesRequiresCA2335=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2336=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2337=== RUN TestPins_ReservedForMatchingRule2338=== PAUSE TestPins_ReservedForMatchingRule2339=== RUN TestPins_TopLevelShorthand2340=== PAUSE TestPins_TopLevelShorthand2341=== RUN TestPins_ConfigValidation2342=== PAUSE TestPins_ConfigValidation2343=== RUN TestScopes_LegacyProviderDefaultsToWrite2344=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2345=== RUN TestScopes_Rules2346=== PAUSE TestScopes_Rules2347=== RUN TestScopes_ConfigValidation2348=== PAUSE TestScopes_ConfigValidation2349=== CONT TestAudienceForIssuer2350--- PASS: TestAudienceForIssuer (0.00s)2351=== CONT TestValidateToken_Expired2352=== CONT TestValidateToken_KubernetesServiceAccount2353=== CONT TestValidateToken_BoundClaimsMismatch2354=== CONT TestValidateToken_MultipleProviders2355=== CONT TestValidateToken_NoMatchingProvider2356=== CONT TestValidateToken_ValidToken2357=== CONT TestGlobMatch2358=== RUN TestGlobMatch/foo_foo2359=== PAUSE TestGlobMatch/foo_foo2360=== CONT TestValidateToken_BoundSubjectMismatch2361=== CONT TestValidateToken_WrongAudience2362=== RUN TestGlobMatch/foo_bar2363=== PAUSE TestGlobMatch/foo_bar2364=== RUN TestGlobMatch/*_2365=== PAUSE TestGlobMatch/*_2366=== RUN TestGlobMatch/*_anything2367=== PAUSE TestGlobMatch/*_anything2368=== RUN TestGlobMatch/foo*_foo2369=== PAUSE TestGlobMatch/foo*_foo2370=== RUN TestGlobMatch/foo*_foobar2371=== PAUSE TestGlobMatch/foo*_foobar2372=== RUN TestGlobMatch/foo*_bar2373=== PAUSE TestGlobMatch/foo*_bar2374=== RUN TestGlobMatch/*bar_bar2375=== PAUSE TestGlobMatch/*bar_bar2376=== RUN TestGlobMatch/*bar_foobar2377=== PAUSE TestGlobMatch/*bar_foobar2378=== RUN TestGlobMatch/*bar_foo2379=== PAUSE TestGlobMatch/*bar_foo2380=== RUN TestGlobMatch/foo*bar_foobar2381=== PAUSE TestGlobMatch/foo*bar_foobar2382=== CONT TestPins_ConfigValidation2383=== CONT TestScopes_ConfigValidation2384=== CONT TestScopes_Rules2385=== CONT TestScopes_LegacyProviderDefaultsToWrite2386=== CONT TestPins_ReservedForMatchingRule2387--- PASS: TestPins_ConfigValidation (0.00s)2388--- PASS: TestScopes_ConfigValidation (0.00s)2389=== CONT TestPins_TopLevelShorthand2390=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2391=== CONT TestNewValidator_KubernetesRequiresCA2392=== RUN TestGlobMatch/foo*bar_foo123bar2393=== PAUSE TestGlobMatch/foo*bar_foo123bar2394=== RUN TestGlobMatch/foo*bar_foobarbaz2395=== PAUSE TestGlobMatch/foo*bar_foobarbaz2396=== RUN TestGlobMatch/*/*_foo/bar2397=== PAUSE TestGlobMatch/*/*_foo/bar2398=== RUN TestGlobMatch/*/*_foo2399=== PAUSE TestGlobMatch/*/*_foo2400=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2401=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2402=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02403=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02404=== RUN TestGlobMatch/refs/*/main_refs/heads/main2405=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2406=== RUN TestGlobMatch/fo?_foo2407=== PAUSE TestGlobMatch/fo?_foo2408=== RUN TestGlobMatch/fo?_fo2409=== PAUSE TestGlobMatch/fo?_fo2410=== RUN TestGlobMatch/fo?_fooo2411=== PAUSE TestGlobMatch/fo?_fooo2412=== RUN TestGlobMatch/?oo_foo2413=== PAUSE TestGlobMatch/?oo_foo2414=== RUN TestGlobMatch/?oo_boo2415=== PAUSE TestGlobMatch/?oo_boo2416=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2417=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2418=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2419=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2420=== CONT TestGlobMatch/foo_foo2421=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2422=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2423=== CONT TestGlobMatch/?oo_boo2424=== CONT TestGlobMatch/?oo_foo2425=== CONT TestGlobMatch/fo?_fooo2426=== CONT TestGlobMatch/fo?_fo2427=== CONT TestGlobMatch/fo?_foo2428=== CONT TestGlobMatch/refs/*/main_refs/heads/main2429=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02430=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2431=== CONT TestGlobMatch/*/*_foo2432=== CONT TestGlobMatch/*/*_foo/bar2433=== CONT TestGlobMatch/foo*bar_foobarbaz2434=== CONT TestGlobMatch/foo*bar_foo123bar2435=== CONT TestGlobMatch/foo*bar_foobar2436=== CONT TestGlobMatch/*bar_foo2437=== CONT TestGlobMatch/*bar_foobar2438=== CONT TestGlobMatch/*bar_bar2439=== CONT TestGlobMatch/foo*_bar2440=== CONT TestGlobMatch/foo*_foobar2441=== CONT TestGlobMatch/foo*_foo2442=== CONT TestGlobMatch/*_anything2443=== CONT TestGlobMatch/*_2444=== CONT TestGlobMatch/foo_bar2445--- PASS: TestGlobMatch (0.04s)2446 --- PASS: TestGlobMatch/foo_foo (0.00s)2447 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2448 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2449 --- PASS: TestGlobMatch/?oo_boo (0.00s)2450 --- PASS: TestGlobMatch/?oo_foo (0.00s)2451 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2452 --- PASS: TestGlobMatch/fo?_fo (0.00s)2453 --- PASS: TestGlobMatch/fo?_foo (0.00s)2454 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2455 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2456 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2457 --- PASS: TestGlobMatch/*/*_foo (0.00s)2458 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2459 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2460 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2461 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2462 --- PASS: TestGlobMatch/*bar_foo (0.00s)2463 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2464 --- PASS: TestGlobMatch/*bar_bar (0.00s)2465 --- PASS: TestGlobMatch/foo*_bar (0.00s)2466 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2467 --- PASS: TestGlobMatch/foo*_foo (0.00s)2468 --- PASS: TestGlobMatch/*_anything (0.00s)2469 --- PASS: TestGlobMatch/*_ (0.00s)2470 --- PASS: TestGlobMatch/foo_bar (0.00s)24712026/11/06 07:11:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54404/oidc2472--- PASS: TestValidateToken_BoundSubjectMismatch (0.06s)24732026/11/06 07:11:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54410/oidc24742026/11/06 07:11:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54408/oidc24752026/11/06 07:11:30 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:544062476--- PASS: TestValidateToken_ValidToken (0.08s)24772026/11/06 07:11:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54412/oidc2478--- PASS: TestValidateToken_WrongAudience (0.09s)2479--- PASS: TestValidateToken_BoundClaimsMismatch (0.09s)24802026/11/06 07:11:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54415/oidc2481--- PASS: TestValidateToken_KubernetesServiceAccount (0.09s)2482--- PASS: TestScopes_Rules (0.10s)24832026/11/06 07:11:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54417/oidc2484--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.11s)24852026/11/06 07:11:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54419/oidc2486--- PASS: TestPins_ReservedForMatchingRule (0.11s)24872026/11/06 07:11:30 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54414/oidc2488--- PASS: TestValidateToken_NoMatchingProvider (0.12s)24892026/11/06 07:11:30 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232490--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.12s)24912026/11/06 07:11:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54425/oidc2492--- PASS: TestPins_TopLevelShorthand (0.12s)24932026/11/06 07:11:30 http: TLS handshake error from 127.0.0.1:54428: remote error: tls: bad certificate2494--- PASS: TestNewValidator_KubernetesRequiresCA (0.13s)24952026/11/06 07:11:30 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:54430/oidc2496--- PASS: TestValidateToken_Expired (0.17s)24972026/11/06 07:11:30 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:54429/oidc24982026/11/06 07:11:30 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:54432/oidc2499--- PASS: TestValidateToken_MultipleProviders (0.17s)2500PASS2501Running hook tests...2502=== RUN TestSendPathsEmpty2503=== PAUSE TestSendPathsEmpty2504=== RUN TestQueueEnqueueAndFetch2505=== PAUSE TestQueueEnqueueAndFetch2506=== RUN TestQueueDeduplication2507=== PAUSE TestQueueDeduplication2508=== RUN TestQueueRemove2509=== PAUSE TestQueueRemove2510=== RUN TestQueueFetchBatchLimit2511=== PAUSE TestQueueFetchBatchLimit2512=== RUN TestQueueRetryMovesToBack2513=== PAUSE TestQueueRetryMovesToBack2514=== RUN TestQueueFetchRemoveLifecycle2515=== PAUSE TestQueueFetchRemoveLifecycle2516=== RUN TestQueueConcurrentWriters2517=== PAUSE TestQueueConcurrentWriters2518=== RUN TestQueueRemoveLargeClosure2519=== PAUSE TestQueueRemoveLargeClosure2520=== RUN TestServerClientIntegration2521--- PASS: TestServerClientIntegration (0.00s)2522=== RUN TestServerQueueError25232026/11/06 07:11:30 ERROR Failed to queue paths error="permission denied" count=12524--- PASS: TestServerQueueError (0.00s)2525=== RUN TestGetListenerSocketActivation2526 server_test.go:145: systemd socket activation does not exist on darwin2527--- SKIP: TestGetListenerSocketActivation (0.00s)2528=== RUN TestServerStalledClientDoesNotBlockShutdown2529=== PAUSE TestServerStalledClientDoesNotBlockShutdown2530=== RUN TestServerBacksOffOnAcceptErrors2531=== PAUSE TestServerBacksOffOnAcceptErrors2532=== RUN TestDrainIsolatesPoisonPath2533=== PAUSE TestDrainIsolatesPoisonPath2534=== RUN TestRunNotBlockedByPoisonHead2535=== PAUSE TestRunNotBlockedByPoisonHead2536=== RUN TestDrainGivesUpWhenServerDown2537=== PAUSE TestDrainGivesUpWhenServerDown2538=== RUN TestFailedPathPrunedByLaterClosure2539=== PAUSE TestFailedPathPrunedByLaterClosure2540=== RUN TestWorkerUploadsAndRemoves2541=== PAUSE TestWorkerUploadsAndRemoves2542=== RUN TestWorkerSkipsGCdPaths2543=== PAUSE TestWorkerSkipsGCdPaths2544=== RUN TestWorkerPrunesClosureDeps2545=== PAUSE TestWorkerPrunesClosureDeps2546=== RUN TestDrainTimeout2547=== PAUSE TestDrainTimeout2548=== RUN TestWorkerRemoveFailureIsNotProgress2549=== PAUSE TestWorkerRemoveFailureIsNotProgress2550=== RUN TestWorkerKeepsPathItCannotStat2551=== PAUSE TestWorkerKeepsPathItCannotStat2552=== CONT TestSendPathsEmpty2553--- PASS: TestSendPathsEmpty (0.00s)2554=== CONT TestWorkerRemoveFailureIsNotProgress2555=== CONT TestServerBacksOffOnAcceptErrors25562026/11/06 07:11:30 ERROR Accept failed error="too many open files"2557=== CONT TestWorkerKeepsPathItCannotStat2558=== CONT TestServerStalledClientDoesNotBlockShutdown2559=== CONT TestQueueRemoveLargeClosure2560=== CONT TestQueueConcurrentWriters2561=== CONT TestQueueFetchRemoveLifecycle2562=== CONT TestQueueRetryMovesToBack2563=== CONT TestQueueFetchBatchLimit2564=== CONT TestQueueRemove2565=== CONT TestQueueDeduplication2566=== CONT TestQueueEnqueueAndFetch2567=== CONT TestDrainIsolatesPoisonPath2568=== CONT TestWorkerUploadsAndRemoves2569=== CONT TestDrainTimeout2570=== CONT TestWorkerPrunesClosureDeps2571=== CONT TestWorkerSkipsGCdPaths2572=== CONT TestDrainGivesUpWhenServerDown2573=== CONT TestFailedPathPrunedByLaterClosure2574=== CONT TestRunNotBlockedByPoisonHead25752026/11/06 07:11:30 ERROR Accept failed error="too many open files"25762026/11/06 07:11:30 INFO Upload queue status pending=22577--- PASS: TestQueueFetchBatchLimit (0.01s)25782026/11/06 07:11:30 INFO Uploading batch count=125792026/11/06 07:11:30 INFO Uploading batch count=225802026/11/06 07:11:30 INFO Uploading batch count=425812026/11/06 07:11:30 ERROR Upload failed error="upload failed" count=425822026/11/06 07:11:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestDrainIsolatesPoisonPath3569892583/002/bbb2583--- PASS: TestQueueRemove (0.01s)25842026/11/06 07:11:30 ERROR Accept failed error="too many open files"2585--- PASS: TestQueueFetchRemoveLifecycle (0.02s)25862026/11/06 07:11:30 INFO Upload queue status pending=225872026/11/06 07:11:30 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestWorkerSkipsGCdPaths3048737108/002/nonexistent25882026/11/06 07:11:30 INFO Uploading batch count=125892026/11/06 07:11:30 ERROR Upload failed error="upload failed" count=125902026/11/06 07:11:30 INFO Uploading batch count=12591--- PASS: TestQueueRetryMovesToBack (0.02s)25922026/11/06 07:11:30 INFO Upload queue status pending=325932026/11/06 07:11:30 INFO Uploading batch count=125942026/11/06 07:11:30 ERROR Upload failed error="upload failed" count=125952026/11/06 07:11:30 INFO Uploading batch count=125962026/11/06 07:11:30 ERROR Upload failed error="upload failed" count=12597--- PASS: TestQueueDeduplication (0.02s)25982026/11/06 07:11:30 INFO Uploading batch count=225992026/11/06 07:11:30 ERROR Upload failed error="upload failed" count=226002026/11/06 07:11:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestDrainGivesUpWhenServerDown1074002816/002/a26012026/11/06 07:11:30 INFO Uploading batch count=126022026/11/06 07:11:30 ERROR Upload failed error="upload failed" count=126032026/11/06 07:11:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestDrainGivesUpWhenServerDown1074002816/002/b26042026/11/06 07:11:30 WARN Cannot stat store path, will retry later path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestWorkerKeepsPathItCannotStat3494546721/002/locked/aaa error="stat /private/var/tb/2/scratch/da980f7a6ee70515/build/TestWorkerKeepsPathItCannotStat3494546721/002/locked/aaa: permission denied"2605--- PASS: TestQueueEnqueueAndFetch (0.02s)26062026/11/06 07:11:30 INFO Uploading batch count=126072026/11/06 07:11:30 ERROR Upload failed error="upload failed" count=126082026/11/06 07:11:30 INFO Uploading batch count=226092026/11/06 07:11:30 ERROR Upload failed error="upload failed" count=226102026/11/06 07:11:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestDrainGivesUpWhenServerDown1074002816/002/c26112026/11/06 07:11:30 WARN Cannot stat store path, will retry later path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestWorkerKeepsPathItCannotStat3494546721/002/locked/aaa error="stat /private/var/tb/2/scratch/da980f7a6ee70515/build/TestWorkerKeepsPathItCannotStat3494546721/002/locked/aaa: permission denied"26122026/11/06 07:11:30 ERROR Drain finished with paths left in queue remaining=126132026/11/06 07:11:30 INFO Upload queue status pending=226142026/11/06 07:11:30 INFO Uploading batch count=126152026/11/06 07:11:30 INFO Uploading batch count=226162026/11/06 07:11:30 WARN Cannot stat store path, will retry later path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestWorkerKeepsPathItCannotStat3494546721/002/locked/aaa error="stat /private/var/tb/2/scratch/da980f7a6ee70515/build/TestWorkerKeepsPathItCannotStat3494546721/002/locked/aaa: permission denied"26172026/11/06 07:11:30 INFO Uploading batch count=126182026/11/06 07:11:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestDrainGivesUpWhenServerDown1074002816/002/d26192026/11/06 07:11:30 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestWorkerRemoveFailureIsNotProgress1246189232/002/nonexistent26202026/11/06 07:11:30 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126212026/11/06 07:11:30 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestWorkerRemoveFailureIsNotProgress1246189232/002/nonexistent26222026/11/06 07:11:30 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126232026/11/06 07:11:30 ERROR Drain finished with paths left in queue remaining=126242026/11/06 07:11:30 INFO Uploading batch count=226252026/11/06 07:11:30 ERROR Upload failed error="upload failed" count=226262026/11/06 07:11:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestDrainGivesUpWhenServerDown1074002816/002/e26272026/11/06 07:11:30 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestWorkerRemoveFailureIsNotProgress1246189232/002/nonexistent26282026/11/06 07:11:30 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126292026/11/06 07:11:30 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/da980f7a6ee70515/build/TestDrainGivesUpWhenServerDown1074002816/002/f2630--- PASS: TestDrainIsolatesPoisonPath (0.02s)26312026/11/06 07:11:30 ERROR Drain finished with paths left in queue remaining=126322026/11/06 07:11:30 ERROR Drain finished with paths left in queue remaining=102633--- PASS: TestFailedPathPrunedByLaterClosure (0.02s)2634--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)2635--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2636--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2637--- PASS: TestWorkerPrunesClosureDeps (0.03s)26382026/11/06 07:11:30 ERROR Accept failed error="too many open files"2639--- PASS: TestWorkerSkipsGCdPaths (0.03s)2640--- PASS: TestWorkerUploadsAndRemoves (0.04s)2641--- PASS: TestQueueRemoveLargeClosure (0.04s)2642--- PASS: TestQueueConcurrentWriters (0.05s)26432026/11/06 07:11:30 ERROR Accept failed error="too many open files"26442026/11/06 07:11:30 ERROR Accept failed error="too many open files"26452026/11/06 07:11:30 ERROR Failed to decode request error="read unix /private/var/tb/2/scratch/da980f7a6ee70515/build/hook971101614/test.sock->: i/o timeout"26462026/11/06 07:11:30 ERROR Failed to write response error="write unix /private/var/tb/2/scratch/da980f7a6ee70515/build/hook971101614/test.sock->: i/o timeout"2647--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26482026/11/06 07:11:30 ERROR Upload failed error="context deadline exceeded" count=226492026/11/06 07:11:30 ERROR Drain finished with paths left in queue remaining=42650--- PASS: TestDrainTimeout (0.21s)26512026/11/06 07:11:30 ERROR Accept failed error="too many open files"26522026/11/06 07:11:31 ERROR Accept failed error="too many open files"2653--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26542026/11/06 07:11:31 INFO Uploading batch count=126552026/11/06 07:11:31 INFO Uploading batch count=126562026/11/06 07:11:31 INFO Uploading batch count=126572026/11/06 07:11:31 ERROR Upload failed error="upload failed" count=126582026/11/06 07:11:31 INFO Uploading batch count=126592026/11/06 07:11:31 ERROR Upload failed error="upload failed" count=126602026/11/06 07:11:31 INFO Uploading batch count=126612026/11/06 07:11:31 ERROR Upload failed error="upload failed" count=126622026/11/06 07:11:31 INFO Uploading batch count=126632026/11/06 07:11:31 ERROR Upload failed error="upload failed" count=126642026/11/06 07:11:31 ERROR Drain finished with paths left in queue remaining=12665--- PASS: TestRunNotBlockedByPoisonHead (1.04s)2666PASS2667Running signing tests...2668=== RUN TestExternalSigner2669=== PAUSE TestExternalSigner2670=== RUN TestExternalSignerWrongPublicKey2671=== PAUSE TestExternalSignerWrongPublicKey2672=== RUN TestExternalSignerErrors2673=== PAUSE TestExternalSignerErrors2674=== RUN TestExternalSignerRestartsAfterCrash2675=== PAUSE TestExternalSignerRestartsAfterCrash2676=== RUN TestExternalSignerProgramErrorKeepsProcess2677=== PAUSE TestExternalSignerProgramErrorKeepsProcess2678=== RUN TestExternalSignerClose2679=== PAUSE TestExternalSignerClose2680=== RUN TestExternalSignerRejectsInvalidPublicKey2681=== PAUSE TestExternalSignerRejectsInvalidPublicKey2682=== RUN TestExternalSignerCancellation2683=== PAUSE TestExternalSignerCancellation2684=== RUN TestGenerateFingerprint2685=== PAUSE TestGenerateFingerprint2686=== RUN TestParseSigningKey2687=== PAUSE TestParseSigningKey2688=== RUN TestSign2689=== PAUSE TestSign2690=== RUN TestSignBatch2691=== PAUSE TestSignBatch2692=== RUN TestNilKeyPublicKey2693=== PAUSE TestNilKeyPublicKey2694=== RUN TestSignErrors2695=== PAUSE TestSignErrors2696=== CONT TestExternalSigner2697=== CONT TestSignBatch2698=== CONT TestNilKeyPublicKey2699--- PASS: TestNilKeyPublicKey (0.00s)2700=== CONT TestExternalSignerProgramErrorKeepsProcess2701=== CONT TestExternalSignerCancellation2702=== CONT TestExternalSignerRejectsInvalidPublicKey2703=== RUN TestExternalSignerRejectsInvalidPublicKey/#002704=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002705=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2706=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2707=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2708=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2709=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2710=== CONT TestExternalSignerClose2711=== CONT TestParseSigningKey2712=== RUN TestParseSigningKey/valid_32-byte_key2713=== PAUSE TestParseSigningKey/valid_32-byte_key2714=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2715=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2716=== RUN TestParseSigningKey/no_colon2717=== PAUSE TestParseSigningKey/no_colon2718=== RUN TestParseSigningKey/empty_name2719=== PAUSE TestParseSigningKey/empty_name2720=== RUN TestParseSigningKey/invalid_base642721=== PAUSE TestParseSigningKey/invalid_base642722=== CONT TestSign2723=== CONT TestExternalSignerRestartsAfterCrash2724=== CONT TestGenerateFingerprint2725=== CONT TestSignErrors2726=== CONT TestExternalSignerWrongPublicKey2727=== CONT TestExternalSignerErrors2728--- PASS: TestSignBatch (0.00s)2729=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2730=== RUN TestGenerateFingerprint/basic_with_references2731=== PAUSE TestGenerateFingerprint/basic_with_references2732=== RUN TestGenerateFingerprint/no_references2733=== PAUSE TestGenerateFingerprint/no_references2734=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2735=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2736--- PASS: TestSign (0.00s)2737=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2738=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2739=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2740=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2741=== CONT TestExternalSignerRejectsInvalidPublicKey/#002742=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2743=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2744=== RUN TestParseSigningKey/wrong_length2745=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2746=== RUN TestExternalSignerErrors/wrong_signatures_shape2747=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2748=== RUN TestSignErrors/nil_key2749=== RUN TestGenerateFingerprint/invalid_nar_hash_length2750=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2751=== PAUSE TestParseSigningKey/wrong_length2752=== RUN TestExternalSignerErrors/missing_signature_name2753=== PAUSE TestExternalSignerErrors/missing_signature_name2754=== PAUSE TestSignErrors/nil_key2755--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.01s)2756 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2757 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2758 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2759 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2760 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2761=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2762=== CONT TestParseSigningKey/empty_name2763=== RUN TestGenerateFingerprint/invalid_store_path_prefix2764=== CONT TestParseSigningKey/wrong_length2765=== CONT TestParseSigningKey/invalid_base642766=== CONT TestParseSigningKey/no_colon2767=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2768=== CONT TestParseSigningKey/valid_32-byte_key2769=== RUN TestExternalSignerErrors/exit_at_startup2770=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2771=== RUN TestSignErrors/nil_narinfo2772=== PAUSE TestExternalSignerErrors/exit_at_startup2773=== RUN TestGenerateFingerprint/invalid_reference_prefix2774=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2775=== CONT TestGenerateFingerprint/basic_with_references2776=== CONT TestGenerateFingerprint/invalid_reference_prefix2777=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2778=== PAUSE TestSignErrors/nil_narinfo2779=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2780--- PASS: TestParseSigningKey (0.02s)2781 --- PASS: TestParseSigningKey/empty_name (0.00s)2782 --- PASS: TestParseSigningKey/no_colon (0.00s)2783 --- PASS: TestParseSigningKey/wrong_length (0.00s)2784 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2785 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2786 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2787=== RUN TestExternalSignerErrors/invalid_JSON2788=== CONT TestGenerateFingerprint/invalid_store_path_prefix2789=== CONT TestGenerateFingerprint/invalid_nar_hash_length2790=== CONT TestGenerateFingerprint/no_references2791--- PASS: TestGenerateFingerprint (0.02s)2792 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2793 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2794 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2795 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2796 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2797 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2798 --- PASS: TestGenerateFingerprint/no_references (0.00s)2799=== RUN TestSignErrors/invalid_narinfo2800=== PAUSE TestSignErrors/invalid_narinfo2801=== PAUSE TestExternalSignerErrors/invalid_JSON2802=== RUN TestSignErrors/canceled2803=== PAUSE TestSignErrors/canceled2804=== CONT TestSignErrors/nil_key2805=== RUN TestExternalSignerErrors/too_few_signatures2806=== PAUSE TestExternalSignerErrors/too_few_signatures2807=== RUN TestExternalSignerErrors/exit_on_request2808=== CONT TestSignErrors/canceled2809=== CONT TestSignErrors/invalid_narinfo2810=== CONT TestSignErrors/nil_narinfo2811--- PASS: TestSignErrors (0.02s)2812 --- PASS: TestSignErrors/nil_key (0.00s)2813 --- PASS: TestSignErrors/canceled (0.00s)2814 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2815 --- PASS: TestSignErrors/nil_narinfo (0.00s)2816=== PAUSE TestExternalSignerErrors/exit_on_request2817=== RUN TestExternalSignerErrors/wrong_shape2818=== PAUSE TestExternalSignerErrors/wrong_shape2819=== RUN TestExternalSignerErrors/wrong_id2820=== PAUSE TestExternalSignerErrors/wrong_id2821=== RUN TestExternalSignerErrors/invalid_signature_base642822=== PAUSE TestExternalSignerErrors/invalid_signature_base642823=== RUN TestExternalSignerErrors/wrong_signature_length2824=== PAUSE TestExternalSignerErrors/wrong_signature_length2825=== RUN TestExternalSignerErrors/program_error2826=== PAUSE TestExternalSignerErrors/program_error2827=== RUN TestExternalSignerErrors/null2828=== PAUSE TestExternalSignerErrors/null2829=== RUN TestExternalSignerErrors/unrequested_key2830=== PAUSE TestExternalSignerErrors/unrequested_key2831=== RUN TestExternalSignerErrors/wrong_signature_name2832=== PAUSE TestExternalSignerErrors/wrong_signature_name2833=== RUN TestExternalSignerErrors/missing_signatures2834=== PAUSE TestExternalSignerErrors/missing_signatures2835=== RUN TestExternalSignerErrors/null_signatures2836=== PAUSE TestExternalSignerErrors/null_signatures2837=== CONT TestExternalSignerErrors/wrong_signatures_shape2838=== CONT TestExternalSignerErrors/wrong_id2839=== CONT TestExternalSignerErrors/wrong_signature_length2840=== CONT TestExternalSignerErrors/null2841=== CONT TestExternalSignerErrors/missing_signatures2842=== CONT TestExternalSignerErrors/null_signatures2843=== CONT TestExternalSignerErrors/program_error2844=== CONT TestExternalSignerErrors/wrong_signature_name2845=== CONT TestExternalSignerErrors/exit_on_request2846=== CONT TestExternalSignerErrors/invalid_signature_base642847=== CONT TestExternalSignerErrors/invalid_JSON2848=== CONT TestExternalSignerErrors/too_few_signatures2849=== CONT TestExternalSignerErrors/wrong_shape2850=== CONT TestExternalSignerErrors/exit_at_startup2851=== CONT TestExternalSignerErrors/missing_signature_name2852=== CONT TestExternalSignerErrors/unrequested_key2853--- PASS: TestExternalSignerCancellation (0.27s)2854--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.44s)2855--- PASS: TestExternalSignerWrongPublicKey (0.63s)2856--- PASS: TestExternalSigner (0.85s)2857--- PASS: TestExternalSignerClose (1.02s)2858--- PASS: TestExternalSignerRestartsAfterCrash (1.23s)2859/private/var/tb/2/scratch/da980f7a6ee70515/build/TestExternalSignerRestartsAfterCrash2432521654/001/sign program: line 7: /private/var/tb/2/scratch/da980f7a6ee70515/build/TestExternalSignerRestartsAfterCrash2432521654/001/sign program.starts: No such file or directory2860--- PASS: TestExternalSignerErrors (0.03s)2861 --- PASS: TestExternalSignerErrors/missing_signatures (1.37s)2862 --- PASS: TestExternalSignerErrors/program_error (1.56s)2863 --- PASS: TestExternalSignerErrors/exit_on_request (1.75s)2864 --- PASS: TestExternalSignerErrors/too_few_signatures (1.95s)2865 --- PASS: TestExternalSignerErrors/null_signatures (2.14s)2866 --- PASS: TestExternalSignerErrors/exit_at_startup (2.33s)2867 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (2.53s)2868 --- PASS: TestExternalSignerErrors/wrong_signature_name (2.72s)2869 --- PASS: TestExternalSignerErrors/wrong_id (2.91s)2870 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (3.11s)2871 --- PASS: TestExternalSignerErrors/null (3.29s)2872 --- PASS: TestExternalSignerErrors/invalid_JSON (3.49s)2873 --- PASS: TestExternalSignerErrors/unrequested_key (3.67s)2874 --- PASS: TestExternalSignerErrors/wrong_signature_length (3.87s)2875 --- PASS: TestExternalSignerErrors/wrong_shape (4.06s)2876 --- PASS: TestExternalSignerErrors/missing_signature_name (4.25s)2877PASS2878Running OpenBao signer tests...2879=== RUN TestSign2880=== PAUSE TestSign2881=== RUN TestSignErrors2882=== PAUSE TestSignErrors2883=== RUN TestServe2884=== PAUSE TestServe2885=== RUN TestServeRejectsGarbage2886=== PAUSE TestServeRejectsGarbage2887=== CONT TestSign2888=== CONT TestServe2889=== CONT TestServeRejectsGarbage2890=== CONT TestSignErrors2891--- PASS: TestServeRejectsGarbage (0.00s)2892=== RUN TestSignErrors/http_error2893=== PAUSE TestSignErrors/http_error2894=== RUN TestSignErrors/invalid_json2895=== PAUSE TestSignErrors/invalid_json2896=== RUN TestSignErrors/no_prefix2897=== PAUSE TestSignErrors/no_prefix2898=== RUN TestSignErrors/invalid_base642899=== PAUSE TestSignErrors/invalid_base642900=== CONT TestSignErrors/http_error2901=== CONT TestSignErrors/no_prefix2902=== CONT TestSignErrors/invalid_json2903=== CONT TestSignErrors/invalid_base642904--- PASS: TestServe (0.00s)2905--- PASS: TestSign (0.01s)2906--- PASS: TestSignErrors (0.00s)2907 --- PASS: TestSignErrors/http_error (0.01s)2908 --- PASS: TestSignErrors/no_prefix (0.01s)2909 --- PASS: TestSignErrors/invalid_base64 (0.01s)2910 --- PASS: TestSignErrors/invalid_json (0.01s)2911PASS