niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #454
· raw
1tribuchet: building on mac022Running client tests...3=== RUN TestDoServerRequestAttachesToken4=== PAUSE TestDoServerRequestAttachesToken5=== RUN TestUploadBuildLog_FileBodyReplayedOnRetry6=== PAUSE TestUploadBuildLog_FileBodyReplayedOnRetry7=== RUN TestRegisterUploadedObjectReusesConnections8=== PAUSE TestRegisterUploadedObjectReusesConnections9=== RUN TestRunGarbageCollection_FinishedOnAnotherReplica10=== PAUSE TestRunGarbageCollection_FinishedOnAnotherReplica11=== RUN TestRunGarbageCollection_NotFoundAfterLocalRun12=== PAUSE TestRunGarbageCollection_NotFoundAfterLocalRun13=== RUN TestCaseHackSuffix14=== PAUSE TestCaseHackSuffix15=== RUN TestFilterOversizedClosures16=== PAUSE TestFilterOversizedClosures17=== RUN TestUploadMultipart_PartsInParallel18=== PAUSE TestUploadMultipart_PartsInParallel19=== RUN TestUploadMultipart_FailedPartBufferNotReused20=== PAUSE TestUploadMultipart_FailedPartBufferNotReused21=== RUN TestPartSizeForNAR22=== PAUSE TestPartSizeForNAR23=== RUN TestUploadMultipart_SupersededByPeer24=== PAUSE TestUploadMultipart_SupersededByPeer25=== RUN TestDumpPathCaseHackMatchesNix26--- PASS: TestDumpPathCaseHackMatchesNix (0.14s)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 TestRunGarbageCollection_NotFoundAfterLocalRun118=== CONT TestUploadMultipart_PartsInParallel119=== CONT TestDumpPathMatchesNix120=== CONT TestRegisterUploadedObjectReusesConnections121=== CONT TestResolveStorePath122=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer123=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess124=== CONT TestRateLimiterFeedback125=== CONT TestPathInfoCACompatibility126=== CONT TestParsePathInfoJSONMultiplePaths127=== CONT TestParsePathInfoJSON128=== CONT TestPathInfoHashCompatibility129=== CONT TestGetStorePathHash130=== CONT TestConvertHashToNix32131=== CONT TestEncodeNixBase32WithRealHash132=== CONT TestEncodeNixBase32133=== CONT TestSupersededNARStillUploadsListing134=== CONT TestDumpPathSingleFile135=== CONT TestUploadMultipart_FailedPartBufferNotReused136=== CONT TestUploadMultipart_SupersededByPeer137=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica138=== CONT TestDumpPathWriterError139=== RUN TestRateLimiterFeedback/429_enables_limiter140=== PAUSE TestRateLimiterFeedback/429_enables_limiter1412026/11/01 17:50:45 WARN Rate limiter enabled after throttle name=server-test rate=5142--- PASS: TestEncodeNixBase32WithRealHash (0.00s)143=== RUN TestSupersededNARStillUploadsListing/small_NAR144=== PAUSE TestSupersededNARStillUploadsListing/small_NAR145=== RUN TestConvertHashToNix32/SRI_format_to_Nix32146=== RUN TestSupersededNARStillUploadsListing/dump_cut_short147=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short148=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails149=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails150=== RUN TestUploadMultipart_SupersededByPeer/exists151=== PAUSE TestUploadMultipart_SupersededByPeer/exists152=== RUN TestEncodeNixBase32/test_string_hash153=== PAUSE TestEncodeNixBase32/test_string_hash154=== CONT TestSetClientTLS155=== RUN TestRateLimiterFeedback/503_enables_limiter156=== PAUSE TestRateLimiterFeedback/503_enables_limiter157--- PASS: TestResolveStorePath (0.00s)158=== RUN TestParsePathInfoJSON/Nix_format159=== PAUSE TestParsePathInfoJSON/Nix_format160=== RUN TestPathInfoCACompatibility/null_ca_field161=== PAUSE TestPathInfoCACompatibility/null_ca_field162=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths163=== RUN TestGetStorePathHash/valid_store_path164=== PAUSE TestGetStorePathHash/valid_store_path165=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32166=== CONT TestScriptTokenEmptyCommand167--- PASS: TestScriptTokenEmptyCommand (0.00s)168=== CONT TestScriptTokenScriptFails169=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry170=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)171=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)172=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths173=== RUN TestUploadMultipart_SupersededByPeer/missing174=== PAUSE TestUploadMultipart_SupersededByPeer/missing175=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter176=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter177=== CONT TestScriptTokenBadJSON178=== RUN TestParsePathInfoJSON/Lix_format179=== PAUSE TestParsePathInfoJSON/Lix_format180=== RUN TestParsePathInfoJSON/empty_input181=== PAUSE TestParsePathInfoJSON/empty_input182=== RUN TestParsePathInfoJSON/whitespace_only183=== PAUSE TestParsePathInfoJSON/whitespace_only184=== RUN TestParsePathInfoJSON/invalid_JSON185=== PAUSE TestParsePathInfoJSON/invalid_JSON186=== RUN TestPathInfoCACompatibility/old_string_format_-_text187=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text188=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive189=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive190=== RUN TestPathInfoCACompatibility/new_structured_format_-_text191=== RUN TestGetStorePathHash/basename_without_hyphen_should_error192=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error193=== RUN TestConvertHashToNix32/already_Nix32_format194=== CONT TestScriptTokenEmptyToken1952026/11/01 17:50:45 INFO Garbage collection started1962026/11/01 17:50:45 INFO Garbage collection started1972026/11/01 17:50:45 WARN Rate limiter enabled after throttle name=server-test rate=51982026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:551701992026/11/01 17:50:45 INFO Garbage collection progress phase=running_on_another_replica failed_uploads_deleted=0 old_closures_deleted=0 objects_marked=0 objects_deleted=0 objects_failed=02002026/11/01 17:50:45 WARN Rate limiter backed off name=server-test rate=52012026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:55170202--- PASS: TestScriptTokenScriptFails (0.02s)203--- PASS: TestDoServerRequestAttachesToken (0.02s)204--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)205=== CONT TestFilterOversizedClosures206=== CONT TestScriptTokenCachesUntilRefresh207=== CONT TestScriptTokenNoExpiryRerunsEveryCall208=== RUN TestEncodeNixBase32/empty_input209=== PAUSE TestEncodeNixBase32/empty_input210=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text211=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method212=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method213=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon214=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon215=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI216=== CONT TestFileTokenEmpty217=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI218=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512219=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512220=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths221=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths222=== CONT TestFileTokenReadsAndCaches223=== PAUSE TestConvertHashToNix32/already_Nix32_format224=== RUN TestConvertHashToNix32/invalid_format225=== PAUSE TestConvertHashToNix32/invalid_format226=== CONT TestCaseHackSuffix227--- PASS: TestFileTokenEmpty (0.00s)228=== CONT TestStreamPushStopsWhenCanceled229--- PASS: TestStreamPushStopsWhenCanceled (0.00s)230=== CONT TestClientSignaturesByStorePath231--- PASS: TestClientSignaturesByStorePath (0.00s)232=== CONT TestStaticToken233--- PASS: TestStaticToken (0.00s)234=== CONT TestStreamPushReportsSkippedPaths235--- PASS: TestStreamPushReportsSkippedPaths (0.00s)236=== CONT TestSetClientTLSErrors237=== CONT TestFileTokenMissing2382026/11/01 17:50:45 WARN Rate limiter enabled after throttle name=s3-test rate=52392026/11/01 17:50:45 WARN Garbage collection finished on another replica. Its statistics are not available here240--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.02s)2412026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55216242=== CONT TestSetClientTLSDoesNotMutateDefaultTransport243=== CONT TestStreamPushIsolatesFailures2442026/11/01 17:50:45 ERROR Upload failed error="bad path" count=3245=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter246=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter247=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error248=== CONT TestStreamPushReportsSignatures249=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error250--- PASS: TestStreamPushIsolatesFailures (0.00s)251=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error252=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error253=== CONT TestShellSplitErrors2542026/11/01 17:50:45 ERROR Upload failed error=boom count=1255--- PASS: TestShellSplitErrors (0.00s)256=== CONT TestStreamPushRequestLine257=== RUN TestSetClientTLS/rejects_connection_without_client_cert258--- PASS: TestStreamPushReportsSignatures (0.00s)259=== CONT TestStreamPushReportsEveryPath260=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert261=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA262=== RUN TestFilterOversizedClosures/no_limit_keeps_everything263=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything264=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped265--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.03s)266=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA267=== RUN TestSetClientTLS/preserves_debug_logging_transport268=== PAUSE TestSetClientTLS/preserves_debug_logging_transport269=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2702026/11/01 17:50:45 ERROR Upload failed error=boom count=1271=== RUN TestFilterOversizedClosures/all_closures_skipped272--- PASS: TestStreamPushReportsEveryPath (0.00s)273=== CONT TestShellSplit274=== CONT TestStreamPushBatchesUnderLoad275=== CONT TestStreamPushGivesUpOnDeadServer276=== CONT TestDoWithRetry_FinalResponseBodyReadable277=== PAUSE TestFilterOversizedClosures/all_closures_skipped278--- PASS: TestShellSplit (0.00s)279=== CONT TestRetryTimeoutOutlastsMaxRetries280=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false281=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false2822026/11/01 17:50:45 ERROR Upload failed error="connection refused" count=202832026/11/01 17:50:45 ERROR Server seems unavailable, giving up on batch untried=17284--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)285=== CONT TestSupersededNARStillUploadsListing/small_NAR286=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true287=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true288=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails289=== CONT TestPartSizeForNAR290=== RUN TestPartSizeForNAR/zero_stays_at_minimum291=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum292=== RUN TestPartSizeForNAR/small_stays_at_minimum293=== PAUSE TestPartSizeForNAR/small_stays_at_minimum294=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum295=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum296=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts297=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts298=== RUN TestPartSizeForNAR/1_TiB299=== PAUSE TestPartSizeForNAR/1_TiB300=== RUN TestPartSizeForNAR/5_TiB_S3_max_object301=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object302=== RUN TestPartSizeForNAR/capped_at_5_GiB303=== PAUSE TestPartSizeForNAR/capped_at_5_GiB304=== CONT TestSupersededNARStillUploadsListing/dump_cut_short305--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.03s)306=== CONT TestUploadMultipart_SupersededByPeer/exists307--- PASS: TestFileTokenMissing (0.01s)308=== CONT TestUploadMultipart_SupersededByPeer/missing309--- PASS: TestScriptTokenEmptyToken (0.03s)310=== CONT TestParsePathInfoJSON/Nix_format311=== CONT TestParsePathInfoJSON/whitespace_only312=== CONT TestParsePathInfoJSON/Lix_format313=== CONT TestParsePathInfoJSON/empty_input314=== CONT TestParsePathInfoJSON/invalid_JSON315--- PASS: TestParsePathInfoJSON (0.01s)316 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)317 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)318 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)319 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)320 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)321=== CONT TestEncodeNixBase32/test_string_hash322=== CONT TestPathInfoCACompatibility/null_ca_field323=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method324=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive325=== CONT TestPathInfoCACompatibility/new_structured_format_-_text326=== CONT TestPathInfoCACompatibility/old_string_format_-_text327--- PASS: TestPathInfoCACompatibility (0.02s)328 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)329 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)330 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)331 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)332 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)333=== CONT TestEncodeNixBase32/empty_input334--- PASS: TestEncodeNixBase32 (0.02s)335 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)336 --- PASS: TestEncodeNixBase32/empty_input (0.00s)337=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)338=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths339=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon340=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512341=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI342--- PASS: TestPathInfoHashCompatibility (0.02s)343 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)344 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)345 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)346 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)347=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths348--- PASS: TestParsePathInfoJSONMultiplePaths (0.02s)349 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)350 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)351=== CONT TestConvertHashToNix32/SRI_format_to_Nix32352=== CONT TestConvertHashToNix32/invalid_format353=== CONT TestConvertHashToNix32/already_Nix32_format354--- PASS: TestConvertHashToNix32 (0.02s)355 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)356 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)357 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)358=== CONT TestRateLimiterFeedback/429_enables_limiter359--- PASS: TestScriptTokenBadJSON (0.03s)360=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter361--- PASS: TestFileTokenReadsAndCaches (0.02s)362=== CONT TestRateLimiterFeedback/503_enables_limiter3632026/11/01 17:50:45 INFO Uploading abc-hello (1.0GB)364=== RUN TestSetClientTLSErrors/missing_cert_file365=== PAUSE TestSetClientTLSErrors/missing_cert_file366=== RUN TestSetClientTLSErrors/missing_key_file367=== PAUSE TestSetClientTLSErrors/missing_key_file368=== RUN TestSetClientTLSErrors/missing_ca_file369=== PAUSE TestSetClientTLSErrors/missing_ca_file370=== RUN TestSetClientTLSErrors/invalid_ca_file371=== PAUSE TestSetClientTLSErrors/invalid_ca_file372=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter3732026/11/01 17:50:45 INFO Uploading abc-hello (1.0GB)374=== CONT TestGetStorePathHash/valid_store_path375=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error376=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error377=== CONT TestSetClientTLS/rejects_connection_without_client_cert378--- PASS: TestStreamPushRequestLine (0.02s)379=== CONT TestSetClientTLS/preserves_debug_logging_transport380=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3812026/11/01 17:50:45 WARN Rate limiter enabled after throttle name=server-test rate=53822026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55259383--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.03s)384=== CONT TestGetStorePathHash/basename_without_hyphen_should_error385--- PASS: TestGetStorePathHash (0.02s)386 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)387 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)388 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)389 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)390=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false391=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true3922026/11/01 17:50:45 WARN Rate limiter enabled after throttle name=server-test rate=53932026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:55266394--- PASS: TestStreamPushBatchesUnderLoad (0.00s)395 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)396 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)397=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3982026/11/01 17:50:45 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb-vm-image nar_size=5000 max_nar_size=2000399=== CONT TestPartSizeForNAR/zero_stays_at_minimum400=== CONT TestPartSizeForNAR/capped_at_5_GiB401=== CONT TestPartSizeForNAR/5_TiB_S3_max_object402=== CONT TestPartSizeForNAR/1_TiB403=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts404=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum405=== CONT TestPartSizeForNAR/small_stays_at_minimum406--- PASS: TestPartSizeForNAR (0.00s)407 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)408 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)409 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)410 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)411 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)412 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)413 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)414=== CONT TestFilterOversizedClosures/no_limit_keeps_everything415=== CONT TestFilterOversizedClosures/all_closures_skipped416=== CONT TestSetClientTLSErrors/missing_cert_file417=== CONT TestSetClientTLSErrors/missing_ca_file418=== CONT TestSetClientTLSErrors/invalid_ca_file419=== CONT TestSetClientTLSErrors/missing_key_file4202026/11/01 17:50:45 WARN Rate limiter backed off name=server-test rate=54212026/11/01 17:50:45 WARN Rate limiter enabled after throttle name=s3-test rate=54222026/11/01 17:50:45 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa-small nar_size=1000 max_nar_size=504232026/11/01 17:50:45 WARN Rate limiter backed off name=server-test rate=54242026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:552554252026/11/01 17:50:45 WARN Rate limiter enabled after throttle name=server-test rate=54262026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:552614272026/11/01 17:50:45 WARN Rate limiter backed off name=server-test rate=5428--- PASS: TestSetClientTLSErrors (0.02s)429 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)430 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)431 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)432 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)433--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.02s)434--- PASS: TestFilterOversizedClosures (0.01s)435 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)436 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)437 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)438--- PASS: TestUploadMultipart_SupersededByPeer (0.01s)439 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)440 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.02s)441--- PASS: TestRateLimiterFeedback (0.02s)442 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)443 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.01s)444 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)445 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)4462026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:552554472026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:552554482026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:552554492026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:552554502026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:55255451--- PASS: TestRegisterUploadedObjectReusesConnections (0.07s)4522026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:552554532026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:552554542026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:552554552026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:552554562026/11/01 17:50:45 http: TLS handshake error from 127.0.0.1:55275: read tcp 127.0.0.1:55220->127.0.0.1:55275: use of closed network connection4572026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:552554582026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:55255459--- PASS: TestSetClientTLS (0.03s)460 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.01s)461 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.02s)462 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)4632026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:55255464--- PASS: TestScriptTokenCachesUntilRefresh (0.06s)4652026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:552554662026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:55255467--- PASS: TestDumpPathWriterError (0.08s)4682026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:552554692026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:552554702026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:552554712026/11/01 17:50:45 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:55255472--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.07s)473--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.08s)474--- PASS: TestDumpPathSingleFile (0.10s)475--- PASS: TestCaseHackSuffix (0.08s)4762026/11/01 17:50:45 INFO Uploading abc-hello (1.0GB)4772026/11/01 17:50:45 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:55256/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:55256/part/24782026/11/01 17:50:45 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"479--- PASS: TestDumpPathMatchesNix (0.17s)480--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.60s)481--- PASS: TestSupersededNARStillUploadsListing (0.00s)482 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.02s)483 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.03s)484 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.60s)485--- PASS: TestUploadMultipart_PartsInParallel (0.65s)4862026/11/01 17:50:46 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55168/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55168/api/uploads/complete4872026/11/01 17:50:46 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4882026/11/01 17:50:46 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55168/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55168/api/uploads/complete4892026/11/01 17:50:46 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"490--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4912026/11/01 17:50:46 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:55168/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:55168/api/uploads/complete4922026/11/01 17:50:46 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"493--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)494PASS495Running server tests...496The files belonging to this database system will be owned by user "_tribuchetbld2".497This user must also own the server process.498499The database cluster will be initialized with locale "C".500The default database encoding has accordingly been set to "SQL_ASCII".501The default text search configuration will be set to "english".502503Data page checksums are enabled.504505creating directory /private/var/tb/2/scratch/fe9bd16a51fa0841/build/postgres1949989318/data ... ok506creating subdirectories ... ok507selecting dynamic shared memory implementation ... posix508selecting default "max_connections" ... 100509selecting default "shared_buffers" ... 128MB510selecting default time zone ... UTC511creating configuration files ... ok512running bootstrap script ... ok513performing post-bootstrap initialization ... ok514syncing data to disk ... ok515516initdb: warning: enabling "trust" authentication for local connections517initdb: 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.518519Success. You can now start the database server using:520521 pg_ctl -D /private/var/tb/2/scratch/fe9bd16a51fa0841/build/postgres1949989318/data -l logfile start522523/private/var/tb/2/scratch/fe9bd16a51fa0841/build/postgres1949989318:5432 - no response5242026-11-01 17:50:46.968 UTC [29733] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5252026-11-01 17:50:46.968 UTC [29733] LOG: listening on Unix socket "/private/var/tb/2/scratch/fe9bd16a51fa0841/build/postgres1949989318/.s.PGSQL.5432"5262026-11-01 17:50:46.971 UTC [29740] LOG: database system was shut down at 2026-11-01 17:50:46 UTC5272026-11-01 17:50:46.972 UTC [29733] LOG: database system is ready to accept connections528/private/var/tb/2/scratch/fe9bd16a51fa0841/build/postgres1949989318:5432 - accepting connections529{"timestamp":"2026-11-01T17:50:47.209917Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"ec02404f-63d6-4b6c-bfe1-4f1a96f3d367","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":10,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(2)"}530{"timestamp":"2026-11-01T17:50:47.318515Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"6158505e-d996-44fd-bfdf-6c027cc41927","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(8)"}531=== RUN TestService_AuthMiddleware532=== PAUSE TestService_AuthMiddleware533=== RUN TestService_AuthMiddleware_MTLSProxyHeader534=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader535=== RUN TestService_AuthMiddleware_MTLSBoundSubjects536=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects537=== RUN TestService_ReadAuthMiddleware538=== PAUSE TestService_ReadAuthMiddleware539=== RUN TestService_AuthMiddleware_OIDC540=== PAUSE TestService_AuthMiddleware_OIDC541=== RUN TestService_RequireScope_OIDC542=== PAUSE TestService_RequireScope_OIDC543=== RUN TestService_ReadScope_PublicByDefault544=== PAUSE TestService_ReadScope_PublicByDefault545=== RUN TestCacheConfigHandler546=== PAUSE TestCacheConfigHandler547=== RUN TestCacheStatsHandler548=== PAUSE TestCacheStatsHandler549=== RUN TestClientCADerivations550=== PAUSE TestClientCADerivations551=== RUN TestClientErrorHandling552=== PAUSE TestClientErrorHandling553=== RUN TestClientIntegration554=== PAUSE TestClientIntegration555=== RUN TestClientMultipleUploads556=== PAUSE TestClientMultipleUploads557=== RUN TestClientWithDependencies558=== PAUSE TestClientWithDependencies559=== RUN TestClientSharedPathCommittedMidPush560=== PAUSE TestClientSharedPathCommittedMidPush561=== RUN TestPinProtectsFromGC562=== PAUSE TestPinProtectsFromGC563=== RUN TestClientPushesUseOnePush564=== PAUSE TestClientPushesUseOnePush565=== RUN TestClientFallsBackToClosures566=== PAUSE TestClientFallsBackToClosures567=== RUN TestDeleteClosuresRacingPins568=== PAUSE TestDeleteClosuresRacingPins569=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock570=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock571=== RUN TestResolveDBConnectionString572=== PAUSE TestResolveDBConnectionString573=== RUN TestConnectWaitsForAPeerMigration574=== PAUSE TestConnectWaitsForAPeerMigration575=== RUN TestLeadElectsOneAndHandsOver576=== PAUSE TestLeadElectsOneAndHandsOver577=== RUN TestLeadIncumbentWinsAfterRestart5782026/11/01 17:50:47 INFO lead: acquired remote=192.0.2.1:12345792026/11/01 17:50:48 INFO lead: released remote=192.0.2.1:12345802026/11/01 17:50:48 INFO lead: acquired remote=192.0.2.1:12345812026/11/01 17:50:49 INFO lead: released remote=192.0.2.1:1234582--- PASS: TestLeadIncumbentWinsAfterRestart (1.94s)583=== RUN TestLeadIncumbentAnnouncesAtOnce584=== PAUSE TestLeadIncumbentAnnouncesAtOnce585=== RUN TestLeadEndsOnShutdown586=== PAUSE TestLeadEndsOnShutdown587=== RUN TestLeadEndsWhenItsConnectionHangs5882026/11/01 17:50:49 INFO lead: acquired remote=192.0.2.1:12345892026-11-01 17:50:50.921 UTC [29782] FATAL: terminating connection due to administrator command5902026/11/01 17:50:51 INFO lead: acquired remote=192.0.2.1:12345912026/11/01 17:50:52 WARN lead: lock connection lost error="timeout: context deadline exceeded"5922026/11/01 17:50:52 INFO lead: released remote=192.0.2.1:12345932026/11/01 17:50:52 INFO lead: released remote=192.0.2.1:1234594--- PASS: TestLeadEndsWhenItsConnectionHangs (2.96s)595=== RUN TestGCAdvisoryLockBlocksConcurrentRun596=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun597=== RUN TestGCBugBareHashReferences598=== PAUSE TestGCBugBareHashReferences599=== RUN TestGCMetrics600=== PAUSE TestGCMetrics601=== RUN TestPushDedupSurvivesConcurrentGC602=== PAUSE TestPushDedupSurvivesConcurrentGC603=== RUN TestDeduplicatedObjectsRecordedAsPending604=== PAUSE TestDeduplicatedObjectsRecordedAsPending605=== RUN TestGCSweepSkipsPendingObjects606=== PAUSE TestGCSweepSkipsPendingObjects607=== RUN TestTombstonedObjectOfferedWithoutWaiting608=== PAUSE TestTombstonedObjectOfferedWithoutWaiting609=== RUN TestGCSweepDeliversEachKeyOnce610=== PAUSE TestGCSweepDeliversEachKeyOnce611=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection612=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection613=== RUN TestForceGCDuringPushOffersSweptObject614=== PAUSE TestForceGCDuringPushOffersSweptObject615=== RUN TestFailedS3DeleteKeepsTombstone616=== PAUSE TestFailedS3DeleteKeepsTombstone617=== RUN TestSweepSkipsRowsLockedByPush618=== PAUSE TestSweepSkipsRowsLockedByPush619=== RUN TestRegisterCompletedObjectNeedsPendingRow620=== PAUSE TestRegisterCompletedObjectNeedsPendingRow621=== RUN TestGetExistingObjectsLocksRows622=== PAUSE TestGetExistingObjectsLocksRows623=== RUN TestSweepRechecksPendingAfterLocking624=== PAUSE TestSweepRechecksPendingAfterLocking625=== RUN TestPushWaitsForSweepHoldingRow626=== PAUSE TestPushWaitsForSweepHoldingRow627=== RUN TestCommitRacingPendingCleanupKeepsObjects628=== PAUSE TestCommitRacingPendingCleanupKeepsObjects629=== RUN TestGCEndsOnShutdown630=== PAUSE TestGCEndsOnShutdown631=== RUN TestGCTaskStore_StartNew632=== PAUSE TestGCTaskStore_StartNew633=== RUN TestGCTaskStore_DeduplicateSameParams634=== PAUSE TestGCTaskStore_DeduplicateSameParams635=== RUN TestGCTaskStore_ConflictDifferentParams636=== PAUSE TestGCTaskStore_ConflictDifferentParams637=== RUN TestGCTaskStore_GetEmpty638=== PAUSE TestGCTaskStore_GetEmpty639=== RUN TestGCTaskStore_GetReturnsLatest640=== PAUSE TestGCTaskStore_GetReturnsLatest641=== RUN TestGCTaskStore_CompletedAllowsNewTask642=== PAUSE TestGCTaskStore_CompletedAllowsNewTask643=== RUN TestGCTaskStore_PhaseUpdates644=== PAUSE TestGCTaskStore_PhaseUpdates645=== RUN TestGCTaskStore_Fail646=== PAUSE TestGCTaskStore_Fail647=== RUN TestGracefulShutdownDrainsInflight648=== PAUSE TestGracefulShutdownDrainsInflight649=== RUN TestService_healthCheckHandler650=== PAUSE TestService_healthCheckHandler651=== RUN TestService_readinessHandler652=== PAUSE TestService_readinessHandler653=== RUN TestGenerateLandingPage654=== PAUSE TestGenerateLandingPage655=== RUN TestCacheConfigHandlerMaxNarSize656=== PAUSE TestCacheConfigHandlerMaxNarSize657=== RUN TestCreatePendingClosureRejectsOversizedNAR658=== PAUSE TestCreatePendingClosureRejectsOversizedNAR659=== RUN TestNARDeduplicationMetadataUploadBug660=== PAUSE TestNARDeduplicationMetadataUploadBug661=== RUN TestMetricsInventory662=== PAUSE TestMetricsInventory663=== RUN TestMetricsCommit664=== PAUSE TestMetricsCommit665=== RUN TestService_NativeMTLS666=== PAUSE TestService_NativeMTLS667=== RUN TestServerTLSConfig668=== PAUSE TestServerTLSConfig669=== RUN TestMultipartCleanup670=== PAUSE TestMultipartCleanup671=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded672=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded673=== RUN TestPendingCleanupUsesOneCutoff674=== PAUSE TestPendingCleanupUsesOneCutoff675=== RUN TestObjectStatsTrigger676=== PAUSE TestObjectStatsTrigger677=== RUN TestObjectStatsUpdatedOncePerCommit678=== PAUSE TestObjectStatsUpdatedOncePerCommit679=== RUN TestOrphanedObjectsGC680=== PAUSE TestOrphanedObjectsGC681=== RUN TestOrphanedObjectsGCStressTest682=== PAUSE TestOrphanedObjectsGCStressTest683=== RUN TestCreatePin_ReservedPins684=== PAUSE TestCreatePin_ReservedPins685=== RUN TestPresentReportsOnlyClosureRoots686=== PAUSE TestPresentReportsOnlyClosureRoots687=== RUN TestPresentRefreshesOnlyStaleClosures688=== PAUSE TestPresentRefreshesOnlyStaleClosures689=== RUN TestPresentNotReportedWhileGCDeletesClosure690=== PAUSE TestPresentNotReportedWhileGCDeletesClosure691=== RUN TestParseSingleRange692=== PAUSE TestParseSingleRange693=== RUN TestProxyHeadersOnlyTrustedOnSocket6942026/11/01 17:50:52 INFO Starting HTTP server address=proxy.sock6952026/11/01 17:50:52 INFO Starting HTTP server address=127.0.0.1:553086962026/11/01 17:50:52 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6972026/11/01 17:50:52 INFO Shutdown signal received, draining in-flight requests timeout=10s698--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)699=== RUN TestIsValidCachePath700=== PAUSE TestIsValidCachePath701=== RUN TestReadProxyNarinfo702=== PAUSE TestReadProxyNarinfo703=== RUN TestReadProxyNarinfoAlreadyDecompressed704=== PAUSE TestReadProxyNarinfoAlreadyDecompressed705=== RUN TestReadProxyContentNegotiation706=== PAUSE TestReadProxyContentNegotiation707=== RUN TestReadProxyNarStreaming708=== PAUSE TestReadProxyNarStreaming709=== RUN TestReadProxy404710=== PAUSE TestReadProxy404711=== RUN TestReadProxyInvalidPath712=== PAUSE TestReadProxyInvalidPath713=== RUN TestReadProxyHead714=== PAUSE TestReadProxyHead715=== RUN TestReadProxyOutlastsServerWriteTimeout716=== PAUSE TestReadProxyOutlastsServerWriteTimeout717=== RUN TestReadProxyConditionalGet718=== PAUSE TestReadProxyConditionalGet719=== RUN TestReadProxyRootRedirectsToIndexHTML720=== PAUSE TestReadProxyRootRedirectsToIndexHTML721=== RUN TestReadProxyDisabled722=== PAUSE TestReadProxyDisabled723=== RUN TestReadRedirectNar724=== PAUSE TestReadRedirectNar725=== RUN TestReadRedirectKeepsNarinfoProxied726=== PAUSE TestReadRedirectKeepsNarinfoProxied727=== RUN TestReadProxyRangeRequest728=== PAUSE TestReadProxyRangeRequest729=== RUN TestReadRedirectUsesPublicS3URL730=== PAUSE TestReadRedirectUsesPublicS3URL731=== RUN TestPush_OverlappingRootsStoreOneRowPerKey732=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey733=== RUN TestPush_CompleteCommitsEveryRoot734=== PAUSE TestPush_CompleteCommitsEveryRoot735=== RUN TestPush_RepeatedRootCommitsOnce736=== PAUSE TestPush_RepeatedRootCommitsOnce737=== RUN TestPush_CompleteWaitsForCleanupOfThePush738=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush739=== RUN TestPush_RootsAreLockedInByteOrder740=== PAUSE TestPush_RootsAreLockedInByteOrder741=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit742=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit743=== RUN TestPush_RejectsBadRequests744=== PAUSE TestPush_RejectsBadRequests745=== RUN TestPush_SignsNarinfosOfItsPendingObjects746=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects747=== RUN TestRedundantMultipartUpload748=== PAUSE TestRedundantMultipartUpload749=== RUN TestCompleteMultipartUpload_ErrorButObjectExists750=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists751=== RUN TestCompletedNarNotReofferedAcrossClosures752=== PAUSE TestCompletedNarNotReofferedAcrossClosures753=== RUN TestPresignedUploadRegisteredBeforeCommit754=== PAUSE TestPresignedUploadRegisteredBeforeCommit755=== RUN TestService_Rustfstest756=== PAUSE TestService_Rustfstest757=== RUN TestParseSize758=== PAUSE TestParseSize759=== RUN TestSkippedUploadsHandler760=== PAUSE TestSkippedUploadsHandler761=== RUN TestSystemdListenerNotActivated762--- PASS: TestSystemdListenerNotActivated (0.00s)763=== RUN TestWatchdogBeatsWhenHealthy764--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)765=== RUN TestWatchdogSkipsWhenUnhealthy7662026/11/01 17:50:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7672026/11/01 17:50:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/11/01 17:50:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/11/01 17:50:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/01 17:50:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/01 17:50:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/01 17:50:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/01 17:50:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/01 17:50:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/01 17:50:52 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"776--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)777=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle778=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle779=== RUN TestProxyWriteTimeout780=== PAUSE TestProxyWriteTimeout781=== RUN TestPendingClosureWriteTimeout782=== PAUSE TestPendingClosureWriteTimeout783=== RUN TestIsValidUploadKey784=== PAUSE TestIsValidUploadKey785=== RUN TestUploadHandlersRejectInvalidKeys786=== PAUSE TestUploadHandlersRejectInvalidKeys787=== RUN TestUploadHandlersRejectOversizedBody788=== PAUSE TestUploadHandlersRejectOversizedBody789=== RUN TestService_cleanupPendingClosuresHandler790=== PAUSE TestService_cleanupPendingClosuresHandler791=== RUN TestService_createPendingClosureHandler792=== PAUSE TestService_createPendingClosureHandler793=== RUN TestService_verifyS3Integrity794=== PAUSE TestService_verifyS3Integrity795=== RUN TestService_verifyS3ReuploadsStaleNarinfo796=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo797=== RUN TestCompleteMultipartUnregistered798=== PAUSE TestCompleteMultipartUnregistered799=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT800=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT801=== CONT TestPush_SignsNarinfosOfItsPendingObjects802=== CONT TestService_AuthMiddleware803=== CONT TestGCTaskStore_PhaseUpdates804=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit805=== CONT TestSkippedUploadsHandler806--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)807=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT808=== CONT TestService_Rustfstest809=== CONT TestCompleteMultipartUnregistered8102026/11/01 17:50:52 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000811=== CONT TestService_verifyS3ReuploadsStaleNarinfo812=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed813=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed814=== CONT TestService_verifyS3Integrity815=== CONT TestService_createPendingClosureHandler816=== CONT TestService_cleanupPendingClosuresHandler817=== CONT TestUploadHandlersRejectOversizedBody818=== CONT TestUploadHandlersRejectInvalidKeys819=== CONT TestIsValidUploadKey820=== CONT TestParseSingleRange821=== CONT TestPush_RejectsBadRequests822=== CONT TestProxyWriteTimeout823=== RUN TestProxyWriteTimeout/narinfo824=== RUN TestIsValidUploadKey/narinfo825=== PAUSE TestProxyWriteTimeout/narinfo826=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle827=== CONT TestPendingClosureWriteTimeout828=== CONT TestPresentNotReportedWhileGCDeletesClosure829=== CONT TestPresentRefreshesOnlyStaleClosures830=== CONT TestPresentReportsOnlyClosureRoots831=== CONT TestCreatePin_ReservedPins832=== CONT TestOrphanedObjectsGCStressTest833=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed834=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed835=== RUN TestParseSingleRange/none836=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost837=== PAUSE TestIsValidUploadKey/narinfo838=== CONT TestOrphanedObjectsGC839=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info840=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info841=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal842=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal843=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key844=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key845=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key846=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key847=== RUN TestIsValidUploadKey/nar_zst848=== CONT TestObjectStatsUpdatedOncePerCommit849=== PAUSE TestIsValidUploadKey/nar_zst850=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost851=== PAUSE TestParseSingleRange/none852=== RUN TestIsValidUploadKey/nar_xz853=== RUN TestParseSingleRange/unknown_unit854=== PAUSE TestParseSingleRange/unknown_unit855=== PAUSE TestIsValidUploadKey/nar_xz856=== RUN TestProxyWriteTimeout/1_GiB_nar857=== RUN TestIsValidUploadKey/nar_plain858=== PAUSE TestProxyWriteTimeout/1_GiB_nar859=== RUN TestProxyWriteTimeout/10_GiB_nar860=== PAUSE TestProxyWriteTimeout/10_GiB_nar861=== PAUSE TestIsValidUploadKey/nar_plain862=== RUN TestIsValidUploadKey/listing863=== PAUSE TestIsValidUploadKey/listing864=== RUN TestIsValidUploadKey/build_log865=== PAUSE TestIsValidUploadKey/build_log866=== RUN TestIsValidUploadKey/build_log_home-manager_file867=== PAUSE TestIsValidUploadKey/build_log_home-manager_file868=== RUN TestIsValidUploadKey/build_log_plus_in_name869=== PAUSE TestIsValidUploadKey/build_log_plus_in_name870=== RUN TestIsValidUploadKey/build_log_question_mark871=== PAUSE TestIsValidUploadKey/build_log_question_mark872=== RUN TestIsValidUploadKey/build_log_equals873=== RUN TestPendingClosureWriteTimeout/empty874=== PAUSE TestPendingClosureWriteTimeout/empty875=== RUN TestPendingClosureWriteTimeout/400_objects876=== PAUSE TestPendingClosureWriteTimeout/400_objects877=== RUN TestPendingClosureWriteTimeout/670k_objects878=== PAUSE TestPendingClosureWriteTimeout/670k_objects879=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline880=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline881=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale882=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale883=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh884=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh885=== CONT TestObjectStatsTrigger886=== CONT TestPendingCleanupUsesOneCutoff887=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed888=== RUN TestParseSingleRange/multi-range_ignored889=== RUN TestProxyWriteTimeout/unknown_size890--- PASS: TestSkippedUploadsHandler (0.00s)891=== PAUSE TestIsValidUploadKey/build_log_equals892=== RUN TestIsValidUploadKey/realisation893=== PAUSE TestIsValidUploadKey/realisation894=== RUN TestIsValidUploadKey/realisation_plus_in_output895=== PAUSE TestIsValidUploadKey/realisation_plus_in_output896=== RUN TestIsValidUploadKey/nix-cache-info897=== PAUSE TestIsValidUploadKey/nix-cache-info898=== RUN TestIsValidUploadKey/index.html899=== PAUSE TestIsValidUploadKey/index.html900=== RUN TestIsValidUploadKey/narinfo_key,_nar_type901=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type902=== RUN TestIsValidUploadKey/nar_key,_narinfo_type903=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type904=== RUN TestIsValidUploadKey/listing_key,_narinfo_type905=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type906=== RUN TestIsValidUploadKey/traversal907=== PAUSE TestIsValidUploadKey/traversal908=== RUN TestIsValidUploadKey/traversal_nar909=== PAUSE TestIsValidUploadKey/traversal_nar910=== RUN TestIsValidUploadKey/absolute911=== PAUSE TestIsValidUploadKey/absolute912=== RUN TestIsValidUploadKey/empty_key913=== PAUSE TestIsValidUploadKey/empty_key914=== RUN TestIsValidUploadKey/unknown_type915=== PAUSE TestIsValidUploadKey/unknown_type916=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed917=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed918=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed919=== PAUSE TestParseSingleRange/multi-range_ignored920=== RUN TestParseSingleRange/malformed_no_dash921=== PAUSE TestParseSingleRange/malformed_no_dash922=== RUN TestParseSingleRange/malformed_both_empty923=== PAUSE TestParseSingleRange/malformed_both_empty924=== RUN TestParseSingleRange/malformed_end_before_start925=== PAUSE TestParseSingleRange/malformed_end_before_start926=== RUN TestParseSingleRange/closed927=== PAUSE TestParseSingleRange/closed928=== RUN TestParseSingleRange/open-ended929=== PAUSE TestParseSingleRange/open-ended930=== RUN TestParseSingleRange/end_clamped_to_size931=== PAUSE TestParseSingleRange/end_clamped_to_size932=== RUN TestParseSingleRange/suffix933=== PAUSE TestParseSingleRange/suffix934=== RUN TestParseSingleRange/suffix_exceeds_size935=== PAUSE TestParseSingleRange/suffix_exceeds_size936=== RUN TestParseSingleRange/single_byte937=== PAUSE TestParseSingleRange/single_byte938=== RUN TestParseSingleRange/start_past_EOF939=== PAUSE TestParseSingleRange/start_past_EOF940=== RUN TestParseSingleRange/start_far_past_EOF941=== PAUSE TestParseSingleRange/start_far_past_EOF942=== PAUSE TestProxyWriteTimeout/unknown_size943=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded944=== CONT TestMultipartCleanup945=== CONT TestServerTLSConfig946=== RUN TestServerTLSConfig/no_client_CA947=== PAUSE TestServerTLSConfig/no_client_CA948=== RUN TestServerTLSConfig/missing_CA_file949=== PAUSE TestServerTLSConfig/missing_CA_file950=== RUN TestServerTLSConfig/not_a_PEM_file951=== PAUSE TestServerTLSConfig/not_a_PEM_file952=== CONT TestService_NativeMTLS953=== CONT TestMetricsCommit9542026/11/01 17:50:52 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55311/oidc955=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure956=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure957=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart958=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart959=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts960=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts961=== CONT TestMetricsInventory9622026/11/01 17:50:54 INFO Received push request method=POST path=/api/pushes9632026/11/01 17:50:54 INFO Received complete push request method=POST path=/api/pushes/1/complete9642026/11/01 17:50:54 INFO Completed push id=1 objects=4 duration=73.104667ms9652026/11/01 17:50:54 INFO Received push request method=POST path=/api/pushes9662026/11/01 17:50:54 INFO Aborted multipart uploads count=0 kept=09672026/11/01 17:50:54 WARN Force mode enabled - objects will be deleted immediately without grace period9682026/11/01 17:50:54 INFO Received uploads request method=POST path=/api/pending_closures9692026/11/01 17:50:54 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=09702026/11/01 17:50:54 INFO Vacuumed table table=pending_closures9712026/11/01 17:50:54 INFO Vacuumed table table=pending_objects9722026/11/01 17:50:54 INFO Vacuumed table table=multipart_uploads9732026/11/01 17:50:54 INFO Vacuumed table table=closures9742026/11/01 17:50:54 INFO Vacuumed table table=objects9752026/11/01 17:50:54 INFO Received complete push request method=POST path=/api/pushes/2/complete9762026/11/01 17:50:54 INFO Completed push id=2 objects=4 duration=7.265084ms977--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.95s)978=== CONT TestNARDeduplicationMetadataUploadBug979=== RUN TestPush_RejectsBadRequests/no_roots980=== PAUSE TestPush_RejectsBadRequests/no_roots981=== RUN TestPush_RejectsBadRequests/no_objects982=== PAUSE TestPush_RejectsBadRequests/no_objects983=== RUN TestPush_RejectsBadRequests/bad_root984=== PAUSE TestPush_RejectsBadRequests/bad_root985=== RUN TestPush_RejectsBadRequests/root_not_in_objects986=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects987=== CONT TestCreatePendingClosureRejectsOversizedNAR9882026/11/01 17:50:54 INFO Received uploads request method=POST path=/api/pending_closures989--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)990=== CONT TestCacheConfigHandlerMaxNarSize991--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)992=== CONT TestGenerateLandingPage993--- PASS: TestGenerateLandingPage (0.00s)994=== CONT TestService_readinessHandler9952026/11/01 17:50:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9962026/11/01 17:50:55 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"997--- PASS: TestService_AuthMiddleware (2.34s)998=== CONT TestService_healthCheckHandler9992026/11/01 17:50:55 INFO Received push request method=POST path=/api/pushes10002026/11/01 17:50:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10012026/11/01 17:50:55 INFO Signed narinfos id=1 count=110022026/11/01 17:50:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10032026/11/01 17:50:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10042026/11/01 17:50:55 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"10052026/11/01 17:50:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10062026/11/01 17:50:55 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"10072026/11/01 17:50:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10082026/11/01 17:50:55 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=110092026/11/01 17:50:55 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10102026/11/01 17:50:55 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1011--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (2.65s)1012=== CONT TestGracefulShutdownDrainsInflight10132026/11/01 17:50:55 INFO Starting HTTP server address=127.0.0.1:5533210142026/11/01 17:50:55 INFO Shutdown signal received, draining in-flight requests timeout=10s1015--- PASS: TestGracefulShutdownDrainsInflight (0.08s)1016=== CONT TestGCTaskStore_Fail1017--- PASS: TestGCTaskStore_Fail (0.00s)1018=== CONT TestParseSize1019--- PASS: TestParseSize (0.00s)1020=== CONT TestReadProxyRootRedirectsToIndexHTML1021--- PASS: TestService_Rustfstest (2.77s)1022=== CONT TestPush_RootsAreLockedInByteOrder10232026/11/01 17:50:55 INFO Received uploads request method=POST path=/api/pending_closures10242026/11/01 17:50:55 WARN mTLS auth: subject not in bound subjects subject="CN=reader"10252026/11/01 17:50:55 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1026--- PASS: TestService_NativeMTLS (3.18s)1027=== CONT TestPush_CompleteWaitsForCleanupOfThePush10282026/11/01 17:50:56 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10292026/11/01 17:50:56 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1030--- PASS: TestCompleteMultipartUnregistered (3.92s)1031=== CONT TestPush_RepeatedRootCommitsOnce10322026/11/01 17:50:57 INFO Received cleanup request method=DELETE path=/api/pending_closures10332026/11/01 17:50:57 INFO Aborted multipart uploads count=0 kept=010342026/11/01 17:50:57 INFO Received uploads request method=POST path=/api/pending_closures10352026/11/01 17:50:57 INFO Received cleanup request method=DELETE path=/api/pending_closures10362026/11/01 17:50:57 INFO Aborted multipart uploads count=1 kept=010372026/11/01 17:50:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10382026-11-01 17:50:57.222 UTC [29862] ERROR: Closure does not exist: id=110392026-11-01 17:50:57.222 UTC [29862] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10402026-11-01 17:50:57.222 UTC [29862] STATEMENT: -- name: CommitPendingClosure :one1041 SELECT commit_pending_closure($1::bigint)::bigint1042 1043--- PASS: TestService_cleanupPendingClosuresHandler (4.49s)1044=== CONT TestPush_CompleteCommitsEveryRoot10452026/11/01 17:50:57 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1046--- PASS: TestPresentReportsOnlyClosureRoots (4.77s)1047=== CONT TestPush_OverlappingRootsStoreOneRowPerKey10482026/11/01 17:50:57 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LjYwOWFlMDM1LTIxMjMtNDJmOC05MWYxLTdlMzg2NTBhMzJiZXgxNzkzNTU1NDU1NzU3ODg0MDAw parts=1010492026/11/01 17:50:57 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10502026/11/01 17:50:57 INFO Completed upload id=1 objects=2 duration=13.7545ms10512026/11/01 17:50:57 INFO Received uploads request method=POST path=/api/pending_closures10522026/11/01 17:50:57 INFO Received uploads request method=POST path=/api/pending_closures10532026/11/01 17:50:57 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10542026/11/01 17:50:57 WARN Found objects in DB but missing from S3, will re-upload count=11055--- PASS: TestService_verifyS3Integrity (4.85s)1056=== CONT TestReadRedirectUsesPublicS3URL10572026/11/01 17:50:57 INFO Received uploads request method=POST path=/api/pending_closures10582026/11/01 17:50:57 INFO Received uploads request method=POST path=/api/pending_closures10592026/11/01 17:50:57 INFO Received uploads request method=POST path=/api/pending_closures1060--- PASS: TestObjectStatsTrigger (5.50s)1061=== CONT TestReadProxyRangeRequest1062=== NAME TestOrphanedObjectsGC1063 orphaned_objects_gc_test.go:287: GC Test Summary:1064 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1065 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1066 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1067 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1068 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1069--- PASS: TestOrphanedObjectsGC (5.75s)1070=== CONT TestReadRedirectKeepsNarinfoProxied10712026/11/01 17:50:58 INFO Received uploads request method=POST path=/api/pending_closures1072--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (6.11s)1073=== CONT TestReadRedirectNar10742026/11/01 17:50:59 INFO Received uploads request method=POST path=/api/pending_closures1075--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (6.43s)1076=== CONT TestReadProxyDisabled10772026/11/01 17:50:59 INFO Received uploads request method=POST path=/api/pending_closures10782026/11/01 17:50:59 INFO Received uploads request method=POST path=/api/pending_closures10792026/11/01 17:50:59 INFO Received cleanup request method=DELETE path=/api/pending_closures10802026/11/01 17:50:59 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10812026/11/01 17:50:59 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LmIxMzdjMGY5LTJhN2UtNGNkOC1hYTFhLTY2Yjc0NzBjMzExNHgxNzkzNTU1NDU3ODc3NTk1MDAw parts=1010822026/11/01 17:50:59 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10832026/11/01 17:50:59 INFO Completed upload id=1 objects=2 duration=23.066083ms10842026/11/01 17:50:59 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010852026/11/01 17:50:59 INFO Received uploads request method=POST path=/api/pending_closures10862026/11/01 17:50:59 INFO Starting cleanup of old closures method=DELETE path=/api/closures10872026/11/01 17:50:59 INFO Aborted multipart uploads count=0 kept=010882026/11/01 17:50:59 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=010892026/11/01 17:50:59 INFO Vacuumed table table=pending_closures10902026/11/01 17:50:59 INFO Vacuumed table table=pending_objects10912026/11/01 17:51:00 INFO Vacuumed table table=multipart_uploads1092--- PASS: TestObjectStatsUpdatedOncePerCommit (7.26s)1093=== CONT TestCompletedNarNotReofferedAcrossClosures10942026/11/01 17:51:00 INFO Vacuumed table table=closures10952026/11/01 17:51:00 INFO Received uploads request method=POST path=/api/pending_closures10962026/11/01 17:51:00 INFO Vacuumed table table=objects10972026/11/01 17:51:00 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001098--- PASS: TestService_createPendingClosureHandler (7.47s)1099=== CONT TestPresignedUploadRegisteredBeforeCommit11002026/11/01 17:51:00 WARN Rate limiter enabled after throttle name=s3-test rate=511012026/11/01 17:51:00 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1102=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1103 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101104 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001105--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (7.60s)1106=== CONT TestReadProxy40411072026/11/01 17:51:00 INFO Received cleanup request method=DELETE path=/api/pending_closures11082026/11/01 17:51:00 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket23/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""11092026/11/01 17:51:00 INFO Aborted multipart uploads count=0 kept=111102026/11/01 17:51:00 INFO Received cleanup request method=DELETE path=/api/pending_closures11112026/11/01 17:51:00 INFO Aborted multipart uploads count=1 kept=01112--- PASS: TestMultipartCleanup (7.67s)1113=== CONT TestReadProxyConditionalGet1114--- PASS: TestPresentRefreshesOnlyStaleClosures (7.91s)1115=== CONT TestReadProxyOutlastsServerWriteTimeout11162026/11/01 17:51:00 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11172026/11/01 17:51:00 WARN Refused reserved pin name=worker-x86_64-linux11182026/11/01 17:51:00 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux11192026/11/01 17:51:00 INFO Received create pin request method=POST path=/api/pins/my-app11202026/11/01 17:51:00 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1121--- PASS: TestCreatePin_ReservedPins (8.21s)1122=== CONT TestReadProxyHead1123--- PASS: TestMetricsInventory (8.48s)1124=== CONT TestReadProxyInvalidPath11252026/11/01 17:51:01 INFO Received push request method=POST path=/api/pushes11262026/11/01 17:51:01 INFO Received complete push request method=POST path=/api/pushes/1/complete11272026/11/01 17:51:01 INFO Completed push id=1 objects=4 duration=40.100792ms11282026/11/01 17:51:01 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete11292026/11/01 17:51:01 INFO Completed upload id=2 objects=2 duration=644.583µs1130--- PASS: TestMetricsCommit (8.93s)1131=== CONT TestReadProxyNarinfoAlreadyDecompressed11322026/11/01 17:51:01 WARN readiness check failed error="closed pool"1133--- PASS: TestService_readinessHandler (7.06s)1134=== CONT TestReadProxyNarStreaming1135--- PASS: TestService_healthCheckHandler (7.35s)1136=== CONT TestReadProxyContentNegotiation1137=== NAME TestNARDeduplicationMetadataUploadBug1138 metadata_upload_test.go:48: First store path: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestNARDeduplicationMetadataUploadBug4291410352/001/store/ab0iccxv6hdpk44mz8lak5x0z0ln3f7y-file1.txt11392026/11/01 17:51:02 INFO Received push request method=POST path=/api/pushes11402026/11/01 17:51:02 INFO Received push request method=POST path=/api/pushes11412026/11/01 17:51:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)11422026/11/01 17:51:02 INFO Uploading ab0iccxv6hdpk44mz8lak5x0z0ln3f7y-file1.txt (160B)11432026/11/01 17:51:02 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"11442026/11/01 17:51:02 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11452026-11-01 17:51:02.869 UTC [29955] ERROR: could not obtain lock on row in relation "closures"11462026-11-01 17:51:02.869 UTC [29955] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11472026/11/01 17:51:02 WARN Failed to register uploaded object key=ab0iccxv6hdpk44mz8lak5x0z0ln3f7y.ls error="server returned 404: 404 page not found\n"11482026/11/01 17:51:02 INFO Signed narinfos id=1 count=111492026/11/01 17:51:02 INFO Uploading 1 narinfos11502026-11-01 17:51:02.875 UTC [29955] ERROR: could not obtain lock on row in relation "closures"11512026-11-01 17:51:02.875 UTC [29955] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11522026-11-01 17:51:02.875 UTC [29955] ERROR: could not obtain lock on row in relation "closures"11532026-11-01 17:51:02.875 UTC [29955] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11542026-11-01 17:51:02.876 UTC [29955] ERROR: could not obtain lock on row in relation "closures"11552026-11-01 17:51:02.876 UTC [29955] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11562026-11-01 17:51:02.881 UTC [29955] ERROR: could not obtain lock on row in relation "closures"11572026-11-01 17:51:02.881 UTC [29955] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1158--- PASS: TestPush_RootsAreLockedInByteOrder (7.39s)1159=== CONT TestCompleteMultipartUpload_ErrorButObjectExists11602026/11/01 17:51:02 INFO Received complete push request method=POST path=/api/pushes/1/complete11612026/11/01 17:51:02 WARN Failed to register uploaded object key=ab0iccxv6hdpk44mz8lak5x0z0ln3f7y.narinfo error="server returned 404: 404 page not found\n"11622026/11/01 17:51:02 INFO Completed push id=1 objects=3 duration=38.885666ms11632026/11/01 17:51:02 INFO Upload complete. (293ms)1164=== NAME TestNARDeduplicationMetadataUploadBug1165 metadata_upload_test.go:54: Retrieved narinfo from S3:1166 StorePath: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestNARDeduplicationMetadataUploadBug4291410352/001/store/ab0iccxv6hdpk44mz8lak5x0z0ln3f7y-file1.txt1167 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1168 Compression: zstd1169 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1170 NarSize: 1601171 References: 1172 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1173 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1174 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1175 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1176--- PASS: TestReadProxyRootRedirectsToIndexHTML (7.58s)1177=== CONT TestGCAdvisoryLockBlocksConcurrentRun1178=== NAME TestNARDeduplicationMetadataUploadBug1179 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestNARDeduplicationMetadataUploadBug4291410352/001/store/57yqqkg0nl543a9qriqh8rj5cbal9nmw-file2.txt11802026/11/01 17:51:03 INFO Received push request method=POST path=/api/pushes11812026/11/01 17:51:03 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)11822026/11/01 17:51:03 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign11832026/11/01 17:51:03 WARN Failed to register uploaded object key=57yqqkg0nl543a9qriqh8rj5cbal9nmw.ls error="server returned 404: 404 page not found\n"11842026/11/01 17:51:03 INFO Signed narinfos id=2 count=111852026/11/01 17:51:03 INFO Uploading 1 narinfos11862026/11/01 17:51:03 INFO Received push request method=POST path=/api/pushes11872026/11/01 17:51:03 INFO Received complete push request method=POST path=/api/pushes/2/complete11882026/11/01 17:51:03 WARN Failed to register uploaded object key=57yqqkg0nl543a9qriqh8rj5cbal9nmw.narinfo error="server returned 404: 404 page not found\n"11892026/11/01 17:51:03 INFO Completed push id=2 objects=3 duration=990.459µs11902026/11/01 17:51:03 INFO Upload complete. (149ms)1191 metadata_upload_test.go:76: Retrieved narinfo from S3:1192 StorePath: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestNARDeduplicationMetadataUploadBug4291410352/001/store/57yqqkg0nl543a9qriqh8rj5cbal9nmw-file2.txt1193 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1194 Compression: zstd1195 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1196 NarSize: 1601197 References: 1198 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1199 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1200 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1201 {"version":1,"root":{"type":"regular","size":44}}1202--- PASS: TestNARDeduplicationMetadataUploadBug (8.64s)1203=== CONT TestGCTaskStore_CompletedAllowsNewTask1204--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1205=== CONT TestGCTaskStore_GetReturnsLatest1206--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1207=== CONT TestGCTaskStore_GetEmpty1208--- PASS: TestGCTaskStore_GetEmpty (0.00s)1209=== CONT TestGCTaskStore_ConflictDifferentParams1210--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1211=== CONT TestGCTaskStore_DeduplicateSameParams1212--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1213=== CONT TestGCTaskStore_StartNew1214--- PASS: TestGCTaskStore_StartNew (0.00s)1215=== CONT TestGCEndsOnShutdown1216=== RUN TestGCEndsOnShutdown/before_the_run1217=== PAUSE TestGCEndsOnShutdown/before_the_run1218=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1219=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1220=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1221=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1222=== CONT TestReadProxyNarinfo12232026/11/01 17:51:03 INFO Received push request method=POST path=/api/pushes12242026/11/01 17:51:03 INFO Received complete push request method=POST path=/api/pushes/1/complete12252026/11/01 17:51:03 INFO Completed push id=1 objects=4 duration=33.22ms1226--- PASS: TestPush_RepeatedRootCommitsOnce (6.98s)1227=== CONT TestRedundantMultipartUpload12282026-11-01 17:51:03.664 UTC [29967] ERROR: Push does not exist: id=112292026-11-01 17:51:03.664 UTC [29967] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE12302026-11-01 17:51:03.664 UTC [29967] STATEMENT: SELECT commit_push($1)1231--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (7.68s)1232=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12332026/11/01 17:51:03 INFO Received push request method=POST path=/api/pushes12342026/11/01 17:51:03 INFO Received complete push request method=POST path=/api/pushes/1/complete12352026/11/01 17:51:03 INFO Completed push id=1 objects=6 duration=45.41225ms1236--- PASS: TestPush_CompleteCommitsEveryRoot (6.69s)1237=== CONT TestPushWaitsForSweepHoldingRow1238--- PASS: TestReadRedirectUsesPublicS3URL (6.55s)1239=== CONT TestSweepRechecksPendingAfterLocking12402026/11/01 17:51:04 INFO Received push request method=POST path=/api/pushes1241--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (7.02s)1242=== CONT TestGetExistingObjectsLocksRows1243--- PASS: TestReadProxyRangeRequest (6.46s)1244=== CONT TestRegisterCompletedObjectNeedsPendingRow1245--- PASS: TestReadRedirectKeepsNarinfoProxied (6.58s)1246=== CONT TestSweepSkipsRowsLockedByPush1247--- PASS: TestReadRedirectNar (6.53s)1248=== CONT TestFailedS3DeleteKeepsTombstone12492026/11/01 17:51:05 INFO Aborted multipart uploads count=1 kept=01250--- PASS: TestReadProxyDisabled (6.37s)1251=== CONT TestForceGCDuringPushOffersSweptObject1252=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1253=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1254=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1255=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1256=== CONT TestIsValidCachePath1257=== RUN TestIsValidCachePath/narinfo1258=== PAUSE TestIsValidCachePath/narinfo1259=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1260=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1261=== RUN TestIsValidCachePath/nar_zst1262=== PAUSE TestIsValidCachePath/nar_zst1263=== RUN TestIsValidCachePath/nar_xz1264=== PAUSE TestIsValidCachePath/nar_xz1265=== RUN TestIsValidCachePath/nar_bz21266=== PAUSE TestIsValidCachePath/nar_bz21267=== RUN TestIsValidCachePath/nar_uncompressed1268=== PAUSE TestIsValidCachePath/nar_uncompressed1269=== RUN TestIsValidCachePath/ls1270=== PAUSE TestIsValidCachePath/ls1271=== RUN TestIsValidCachePath/log1272=== PAUSE TestIsValidCachePath/log1273=== RUN TestIsValidCachePath/realisation1274=== PAUSE TestIsValidCachePath/realisation1275=== RUN TestIsValidCachePath/nix-cache-info1276=== PAUSE TestIsValidCachePath/nix-cache-info1277=== RUN TestIsValidCachePath/index.html1278=== PAUSE TestIsValidCachePath/index.html1279=== RUN TestIsValidCachePath/traversal_parent1280=== PAUSE TestIsValidCachePath/traversal_parent1281=== RUN TestIsValidCachePath/traversal_in_middle1282=== PAUSE TestIsValidCachePath/traversal_in_middle1283=== RUN TestIsValidCachePath/invalid_char_e1284=== PAUSE TestIsValidCachePath/invalid_char_e1285=== RUN TestIsValidCachePath/invalid_char_u1286=== PAUSE TestIsValidCachePath/invalid_char_u1287=== RUN TestIsValidCachePath/random_path1288=== PAUSE TestIsValidCachePath/random_path1289=== RUN TestIsValidCachePath/empty1290=== PAUSE TestIsValidCachePath/empty1291=== RUN TestIsValidCachePath/leading_slash1292=== PAUSE TestIsValidCachePath/leading_slash1293=== RUN TestIsValidCachePath/wrong_extension1294=== PAUSE TestIsValidCachePath/wrong_extension1295=== RUN TestIsValidCachePath/short_hash1296=== PAUSE TestIsValidCachePath/short_hash1297=== CONT TestDeduplicatedObjectsRecordedAsPending12982026/11/01 17:51:05 INFO Received cleanup request method=DELETE path=/api/pending_closures12992026/11/01 17:51:05 INFO Aborted multipart uploads count=1 kept=01300--- PASS: TestPendingCleanupUsesOneCutoff (12.86s)1301=== CONT TestGCSweepDeliversEachKeyOnce13022026/11/01 17:51:05 INFO Received uploads request method=POST path=/api/pending_closures1303=== NAME TestOrphanedObjectsGCStressTest1304 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains13052026/11/01 17:51:06 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst13062026/11/01 17:51:06 INFO Received uploads request method=POST path=/api/pending_closures1307--- PASS: TestPresignedUploadRegisteredBeforeCommit (5.80s)1308=== CONT TestTombstonedObjectOfferedWithoutWaiting1309=== NAME TestOrphanedObjectsGCStressTest1310 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion13112026/11/01 17:51:06 INFO Received uploads request method=POST path=/api/pending_closures1312--- PASS: TestReadProxyConditionalGet (6.41s)1313=== CONT TestGCSweepSkipsPendingObjects1314--- PASS: TestReadProxy404 (6.79s)1315=== CONT TestGCMetrics1316--- PASS: TestReadProxyHead (6.69s)1317=== CONT TestPushDedupSurvivesConcurrentGC1318--- PASS: TestReadProxyInvalidPath (6.59s)1319=== CONT TestGCBugBareHashReferences13202026/11/01 17:51:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13212026/11/01 17:51:08 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LjBjNTM5YjdhLWVhZTEtNGEzZS05MTQ2LWRkMTFjNWM0Zjc3ZHgxNzkzNTU1NDY2MTU1MjY2MDAw parts=1213222026/11/01 17:51:08 INFO Received uploads request method=POST path=/api/pending_closures1323--- PASS: TestCompletedNarNotReofferedAcrossClosures (8.25s)1324=== CONT TestClientWithDependencies1325--- PASS: TestReadProxyNarinfoAlreadyDecompressed (6.65s)1326=== CONT TestLeadEndsOnShutdown1327--- PASS: TestReadProxyNarStreaming (6.92s)1328=== CONT TestLeadIncumbentAnnouncesAtOnce1329--- PASS: TestReadProxyContentNegotiation (6.72s)1330=== CONT TestLeadElectsOneAndHandsOver13312026/11/01 17:51:09 INFO Received uploads request method=POST path=/api/pending_closures13322026/11/01 17:51:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13332026/11/01 17:51:09 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LjVlZmIzNTMxLTRiZjgtNGUyMS04MDRhLWFhODA2NzMxYzgxMHgxNzkzNTU1NDY5MzMwMzA0MDAw13342026/11/01 17:51:09 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"1335--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (6.63s)1336=== CONT TestConnectWaitsForAPeerMigration13372026/11/01 17:51:09 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LjVlZmIzNTMxLTRiZjgtNGUyMS04MDRhLWFhODA2NzMxYzgxMHgxNzkzNTU1NDY5MzMwMzA0MDAw parts=11338--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (6.81s)1339=== CONT TestResolveDBConnectionString1340=== RUN TestResolveDBConnectionString/flag_wins1341=== PAUSE TestResolveDBConnectionString/flag_wins1342=== RUN TestResolveDBConnectionString/file_when_flag_empty1343=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1344=== RUN TestResolveDBConnectionString/missing_file_is_an_error1345=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1346=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1347=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1348=== RUN TestResolveDBConnectionString/nothing_configured1349=== PAUSE TestResolveDBConnectionString/nothing_configured1350=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock13512026/11/01 17:51:10 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1352--- PASS: TestReadProxyNarinfo (6.73s)1353=== CONT TestDeleteClosuresRacingPins13542026/11/01 17:51:10 INFO Received uploads request method=POST path=/api/pending_closures13552026/11/01 17:51:10 INFO Received uploads request method=POST path=/api/pending_closures13562026/11/01 17:51:10 INFO Received uploads request method=POST path=/api/pending_closures1357--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (7.27s)1358=== CONT TestClientFallsBackToClosures13592026/11/01 17:51:11 INFO Received uploads request method=POST path=/api/pending_closures1360--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.87s)1361=== CONT TestClientPushesUseOnePush1362--- PASS: TestPushWaitsForSweepHoldingRow (7.63s)1363=== CONT TestPinProtectsFromGC13642026/11/01 17:51:11 INFO Aborted multipart uploads count=0 kept=013652026/11/01 17:51:11 WARN Force mode enabled - objects will be deleted immediately without grace period13662026/11/01 17:51:11 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=013672026/11/01 17:51:11 INFO Vacuumed table table=pending_closures13682026/11/01 17:51:11 INFO Vacuumed table table=pending_objects13692026/11/01 17:51:11 INFO Vacuumed table table=multipart_uploads13702026/11/01 17:51:11 INFO Vacuumed table table=closures13712026/11/01 17:51:11 INFO Vacuumed table table=objects1372--- PASS: TestSweepRechecksPendingAfterLocking (7.66s)1373=== CONT TestClientSharedPathCommittedMidPush1374--- PASS: TestGetExistingObjectsLocksRows (7.34s)1375=== CONT TestCacheConfigHandler1376=== RUN TestCacheConfigHandler/full_config,_no_issuer1377=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1378=== RUN TestCacheConfigHandler/no_cache_url_configured1379=== PAUSE TestCacheConfigHandler/no_cache_url_configured1380=== RUN TestCacheConfigHandler/no_signing_keys1381=== PAUSE TestCacheConfigHandler/no_signing_keys1382=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1383=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1384=== CONT TestClientMultipleUploads1385--- PASS: TestRegisterCompletedObjectNeedsPendingRow (7.41s)1386=== CONT TestClientIntegration13872026/11/01 17:51:12 INFO Received complete multipart upload request method=POST path=/api/multipart/complete13882026/11/01 17:51:12 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LjUzMzBhYWRkLTllYzctNDk0NS1iZWZmLTQ3NTY4ODlmYjhjZngxNzkzNTU1NDcwMzQ3MDM0MDAw parts=1213892026/11/01 17:51:12 INFO Received uploads request method=POST path=/api/pending_closures13902026/11/01 17:51:12 INFO Received uploads request method=POST path=/api/pending_closures13912026/11/01 17:51:12 INFO Aborted multipart uploads count=0 kept=013922026/11/01 17:51:12 WARN Force mode enabled - objects will be deleted immediately without grace period13932026/11/01 17:51:12 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=013942026/11/01 17:51:12 INFO Vacuumed table table=pending_closures13952026/11/01 17:51:12 INFO Vacuumed table table=pending_objects13962026/11/01 17:51:12 INFO Vacuumed table table=multipart_uploads13972026/11/01 17:51:12 INFO Vacuumed table table=closures13982026/11/01 17:51:12 INFO Vacuumed table table=objects13992026/11/01 17:51:12 INFO Aborted multipart uploads count=0 kept=014002026/11/01 17:51:12 WARN Force mode enabled - objects will be deleted immediately without grace period14012026/11/01 17:51:12 INFO Received uploads request method=POST path=/api/pending_closures14022026/11/01 17:51:13 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=014032026/11/01 17:51:13 INFO Vacuumed table table=pending_closures14042026/11/01 17:51:13 INFO Vacuumed table table=pending_objects14052026/11/01 17:51:13 INFO Vacuumed table table=multipart_uploads14062026/11/01 17:51:13 INFO Vacuumed table table=closures14072026/11/01 17:51:13 INFO Vacuumed table table=objects1408--- PASS: TestSweepSkipsRowsLockedByPush (8.20s)1409=== CONT TestClientErrorHandling1410=== RUN TestClientErrorHandling/InvalidStorePath1411=== PAUSE TestClientErrorHandling/InvalidStorePath1412=== RUN TestClientErrorHandling/InvalidAuthToken1413=== PAUSE TestClientErrorHandling/InvalidAuthToken1414=== RUN TestClientErrorHandling/ServerNotAvailable1415=== PAUSE TestClientErrorHandling/ServerNotAvailable1416=== CONT TestClientCADerivations14172026/11/01 17:51:13 INFO Aborted multipart uploads count=0 kept=014182026/11/01 17:51:13 INFO Received uploads request method=POST path=/api/pending_closures14192026/11/01 17:51:13 WARN Force mode enabled - objects will be deleted immediately without grace period14202026/11/01 17:51:13 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."14212026/11/01 17:51:13 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1422--- PASS: TestFailedS3DeleteKeepsTombstone (8.08s)1423=== CONT TestCacheStatsHandler1424--- PASS: TestDeduplicatedObjectsRecordedAsPending (7.88s)1425=== CONT TestService_AuthMiddleware_OIDC14262026/11/01 17:51:13 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55544/oidc14272026/11/01 17:51:14 INFO Aborted multipart uploads count=0 kept=014282026/11/01 17:51:14 WARN Force mode enabled - objects will be deleted immediately without grace period14292026/11/01 17:51:14 INFO Received uploads request method=POST path=/api/pending_closures1430--- PASS: TestTombstonedObjectOfferedWithoutWaiting (8.34s)1431=== CONT TestService_ReadScope_PublicByDefault14322026/11/01 17:51:14 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=014332026/11/01 17:51:14 INFO Vacuumed table table=pending_closures14342026/11/01 17:51:14 INFO Received uploads request method=POST path=/api/pending_closures14352026/11/01 17:51:14 INFO Vacuumed table table=pending_objects14362026/11/01 17:51:14 INFO Vacuumed table table=multipart_uploads14372026/11/01 17:51:14 INFO Vacuumed table table=closures14382026/11/01 17:51:14 INFO Vacuumed table table=objects1439--- PASS: TestGCSweepDeliversEachKeyOnce (9.22s)1440=== CONT TestService_RequireScope_OIDC14412026/11/01 17:51:14 INFO Aborted multipart uploads count=0 kept=014422026/11/01 17:51:14 WARN Force mode enabled - objects will be deleted immediately without grace period14432026/11/01 17:51:14 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=014442026/11/01 17:51:14 INFO Vacuumed table table=pending_closures14452026/11/01 17:51:15 INFO Vacuumed table table=pending_objects14462026/11/01 17:51:15 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55552/oidc14472026/11/01 17:51:15 INFO Vacuumed table table=multipart_uploads14482026/11/01 17:51:15 INFO Vacuumed table table=closures14492026/11/01 17:51:15 INFO Vacuumed table table=objects14502026/11/01 17:51:15 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1451--- PASS: TestGCSweepSkipsPendingObjects (8.25s)1452=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14532026/11/01 17:51:15 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LmUwNGI2ZmM2LTEzMzktNDBhZC1hMjViLWRlMzJmZjM0ZDQ3YXgxNzkzNTU1NDcyNzAxMDg1MDAw error="Get \"http://127.0.0.1:1/bucket55/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"14542026/11/01 17:51:15 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LjNiOTI5YjdhLTA1ZjEtNDMyOS1iNjlhLWE4OTVlY2I1NGRlMngxNzkzNTU1NDcyNjU0ODE4MDAw parts=1214552026/11/01 17:51:15 INFO Aborted multipart uploads count=0 kept=014562026/11/01 17:51:15 INFO Received cleanup request method=DELETE path=/api/pending_closures14572026/11/01 17:51:15 INFO Aborted multipart uploads count=1 kept=014582026/11/01 17:51:15 WARN Force mode enabled - objects will be deleted immediately without grace period1459--- PASS: TestRedundantMultipartUpload (11.67s)1460=== CONT TestService_ReadAuthMiddleware14612026/11/01 17:51:15 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014622026/11/01 17:51:15 INFO Vacuumed table table=pending_closures14632026/11/01 17:51:15 INFO Vacuumed table table=pending_objects14642026/11/01 17:51:15 INFO Vacuumed table table=multipart_uploads14652026/11/01 17:51:15 INFO Vacuumed table table=closures14662026/11/01 17:51:15 INFO Vacuumed table table=objects1467--- PASS: TestGCMetrics (8.22s)1468=== CONT TestService_AuthMiddleware_MTLSProxyHeader14692026/11/01 17:51:15 INFO Received uploads request method=POST path=/api/pending_closures14702026/11/01 17:51:16 INFO Aborted multipart uploads count=0 kept=014712026/11/01 17:51:16 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=014722026/11/01 17:51:16 INFO Vacuumed table table=pending_closures14732026/11/01 17:51:16 INFO Vacuumed table table=pending_objects14742026/11/01 17:51:16 INFO Vacuumed table table=multipart_uploads14752026/11/01 17:51:16 INFO Vacuumed table table=closures14762026/11/01 17:51:16 INFO Vacuumed table table=objects14772026/11/01 17:51:16 INFO Aborted multipart uploads count=0 kept=014782026/11/01 17:51:16 WARN Force mode enabled - objects will be deleted immediately without grace period14792026/11/01 17:51: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=014802026/11/01 17:51:16 INFO Vacuumed table table=pending_closures14812026/11/01 17:51:16 INFO Vacuumed table table=pending_objects14822026/11/01 17:51:16 INFO Vacuumed table table=multipart_uploads14832026/11/01 17:51:16 INFO Vacuumed table table=closures14842026/11/01 17:51:16 INFO Vacuumed table table=objects1485--- PASS: TestPushDedupSurvivesConcurrentGC (8.89s)1486=== CONT TestCommitRacingPendingCleanupKeepsObjects14872026/11/01 17:51:16 INFO lead: acquired remote=192.0.2.1:12341488--- PASS: TestGCBugBareHashReferences (8.67s)1489=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info14902026/11/01 17:51:16 INFO Received uploads request method=POST path=/1491=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key14922026/11/01 17:51:16 INFO Received request for more parts method=POST path=/1493=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal14942026/11/01 17:51:16 INFO Received uploads request method=POST path=/1495=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key14962026/11/01 17:51:16 INFO Received complete multipart upload request method=POST path=/1497--- PASS: TestUploadHandlersRejectInvalidKeys (0.06s)1498 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1499 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1500 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1501 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1502=== CONT TestPendingClosureWriteTimeout/empty1503=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale15042026/11/01 17:51:17 INFO lead: acquired remote=192.0.2.1:123415052026/11/01 17:51:17 INFO lead: released remote=192.0.2.1:12341506--- PASS: TestLeadIncumbentAnnouncesAtOnce (8.51s)1507=== CONT TestPendingClosureWriteTimeout/400_objects1508=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline15092026/11/01 17:51:17 INFO lead: acquired remote=192.0.2.1:123415102026/11/01 17:51:17 INFO lead: released remote=192.0.2.1:12341511--- PASS: TestLeadEndsOnShutdown (9.31s)1512=== CONT TestPendingClosureWriteTimeout/670k_objects1513=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1514=== NAME TestClientWithDependencies1515 client_integration_test.go:660: Built derivation: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientWithDependencies2660457805/001/store/8lngazl5gpm0hmf63zhc7hvvi8nkqbjl-test-script1516 client_integration_test.go:662: Found 1 dependencies (including self)15172026/11/01 17:51:17 INFO Received push request method=POST path=/api/pushes15182026/11/01 17:51:17 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15192026/11/01 17:51:17 INFO Uploading 8lngazl5gpm0hmf63zhc7hvvi8nkqbjl-test-script (136B)15202026/11/01 17:51:17 WARN Failed to register uploaded object key=8lngazl5gpm0hmf63zhc7hvvi8nkqbjl.ls error="server returned 404: 404 page not found\n"15212026/11/01 17:51:18 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"15222026/11/01 17:51:18 WARN Failed to register uploaded object key=log/6xf6yilnllsafvbg9wanxbb1w7wimr84-test-script.drv error="server returned 404: 404 page not found\n"15232026/11/01 17:51:18 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15242026/11/01 17:51:18 INFO Signed narinfos id=1 count=115252026/11/01 17:51:18 INFO Uploading 1 narinfos15262026/11/01 17:51:18 INFO Received complete push request method=POST path=/api/pushes/1/complete15272026/11/01 17:51:18 WARN Failed to register uploaded object key=8lngazl5gpm0hmf63zhc7hvvi8nkqbjl.narinfo error="server returned 404: 404 page not found\n"15282026/11/01 17:51:18 INFO Completed push id=1 objects=4 duration=29.916875ms15292026/11/01 17:51:18 INFO Upload complete. (270ms)1530 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientWithDependencies2660457805/001/store) requires matching store prefix1531--- PASS: TestClientWithDependencies (9.92s)1532=== CONT TestIsValidUploadKey/narinfo1533=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1534--- PASS: TestConnectWaitsForAPeerMigration (8.84s)1535=== CONT TestParseSingleRange/none1536=== CONT TestProxyWriteTimeout/narinfo1537=== CONT TestIsValidUploadKey/unknown_type1538=== CONT TestIsValidUploadKey/empty_key1539=== CONT TestIsValidUploadKey/absolute1540=== CONT TestIsValidUploadKey/traversal_nar1541=== CONT TestIsValidUploadKey/traversal1542=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1543=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1544=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1545=== CONT TestIsValidUploadKey/index.html1546=== CONT TestIsValidUploadKey/nix-cache-info1547=== CONT TestIsValidUploadKey/realisation_plus_in_output1548=== CONT TestIsValidUploadKey/realisation1549=== CONT TestIsValidUploadKey/build_log_equals1550=== CONT TestIsValidUploadKey/build_log_question_mark1551=== CONT TestIsValidUploadKey/build_log_plus_in_name1552=== CONT TestIsValidUploadKey/build_log_home-manager_file1553=== CONT TestIsValidUploadKey/build_log1554=== CONT TestIsValidUploadKey/listing1555=== CONT TestIsValidUploadKey/nar_plain1556=== CONT TestIsValidUploadKey/nar_xz1557=== CONT TestIsValidUploadKey/nar_zst1558--- PASS: TestIsValidUploadKey (0.07s)1559 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1560 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1561 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1562 --- PASS: TestIsValidUploadKey/absolute (0.00s)1563 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1564 --- PASS: TestIsValidUploadKey/traversal (0.00s)1565 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1566 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1567 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1568 --- PASS: TestIsValidUploadKey/index.html (0.00s)1569 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1570 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1571 --- PASS: TestIsValidUploadKey/realisation (0.00s)1572 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1573 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1574 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1575 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1576 --- PASS: TestIsValidUploadKey/build_log (0.00s)1577 --- PASS: TestIsValidUploadKey/listing (0.00s)1578 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1579 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1580 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1581=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed15822026/11/01 17:51:18 INFO lead: released remote=192.0.2.1:123415832026/11/01 17:51:18 INFO lead: acquired remote=192.0.2.1:123415842026/11/01 17:51:19 INFO Received uploads request method=POST path=/api/pending_closures1585=== NAME TestPinProtectsFromGC1586 client_integration_test.go:778: Pinned store path: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestPinProtectsFromGC4146695739/001/store/n4975kfynf85gwnbdbx41f6vgrih047r-pinned-file.txt1587 client_integration_test.go:779: Unpinned store path: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestPinProtectsFromGC4146695739/001/store/cwfgdffqpn9m0rjmg6drigy9az8dgn3h-unpinned-file.txt15882026/11/01 17:51:19 INFO Received uploads request method=POST path=/api/pending_closures15892026/11/01 17:51:19 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15902026/11/01 17:51:19 INFO Uploading 2c81za2xxy9lzgp4vc09n6qlflylmq72-b (256B)15912026/11/01 17:51:19 INFO Uploading xqnwz3zgjwp509gx35pbv93cz0y6pph7-shared-dep (136B)1592--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (9.35s)1593=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed15942026/11/01 17:51:19 WARN Failed to register uploaded object key=7zizqj2c2jfcdf84zbw51d6bpsnvasgy.ls error="server returned 404: 404 page not found\n"15952026/11/01 17:51:19 WARN Failed to register uploaded object key=2c81za2xxy9lzgp4vc09n6qlflylmq72.ls error="server returned 404: 404 page not found\n"15962026/11/01 17:51:19 WARN Failed to register uploaded object key=nar/02f0ggrasl6cmmcy6yqhfjr77ip21l2ws6ny1hxxpnpq719w870d.nar.zst error="server returned 404: 404 page not found\n"15972026/11/01 17:51:19 INFO Received push request method=POST path=/api/pushes15982026/11/01 17:51:19 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15992026/11/01 17:51:19 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16002026/11/01 17:51:19 WARN Failed to register uploaded object key=xqnwz3zgjwp509gx35pbv93cz0y6pph7.ls error="server returned 404: 404 page not found\n"16012026/11/01 17:51:19 INFO Signed narinfos id=1 count=216022026/11/01 17:51:19 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16032026/11/01 17:51:19 INFO Signed narinfos id=2 count=216042026/11/01 17:51:19 INFO Uploading 4 narinfos16052026/11/01 17:51:19 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16062026/11/01 17:51:19 INFO Uploading n4975kfynf85gwnbdbx41f6vgrih047r-pinned-file.txt (128B)16072026/11/01 17:51:19 WARN Failed to register uploaded object key=xqnwz3zgjwp509gx35pbv93cz0y6pph7.narinfo error="server returned 404: 404 page not found\n"16082026/11/01 17:51:19 WARN Failed to register uploaded object key=2c81za2xxy9lzgp4vc09n6qlflylmq72.narinfo error="server returned 404: 404 page not found\n"16092026/11/01 17:51:19 WARN Failed to register uploaded object key=7zizqj2c2jfcdf84zbw51d6bpsnvasgy.narinfo error="server returned 404: 404 page not found\n"16102026/11/01 17:51:19 WARN Failed to register uploaded object key=n4975kfynf85gwnbdbx41f6vgrih047r.ls error="server returned 404: 404 page not found\n"16112026/11/01 17:51:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16122026/11/01 17:51:19 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"16132026/11/01 17:51:19 INFO Signed narinfos id=1 count=116142026/11/01 17:51:19 INFO Uploading 1 narinfos16152026/11/01 17:51:19 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16162026/11/01 17:51:19 WARN Failed to register uploaded object key=xqnwz3zgjwp509gx35pbv93cz0y6pph7.narinfo error="server returned 404: 404 page not found\n"16172026/11/01 17:51:19 INFO Completed upload id=1 objects=6 duration=11.90425ms16182026/11/01 17:51:19 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16192026/11/01 17:51:19 INFO Received complete push request method=POST path=/api/pushes/1/complete16202026/11/01 17:51:19 WARN Failed to register uploaded object key=n4975kfynf85gwnbdbx41f6vgrih047r.narinfo error="server returned 404: 404 page not found\n"16212026/11/01 17:51:19 INFO Completed upload id=2 objects=6 duration=543.459µs16222026/11/01 17:51:19 INFO Upload complete. (437ms)1623=== NAME TestClientFallsBackToClosures1624 client_pushes_test.go:112: Retrieved narinfo from S3:1625 StorePath: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientFallsBackToClosures2224251223/001/store/xqnwz3zgjwp509gx35pbv93cz0y6pph7-shared-dep1626 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1627 Compression: zstd1628 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821629 NarSize: 1361630 References: 1631 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1632 client_pushes_test.go:112: Retrieved narinfo from S3:1633 StorePath: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientFallsBackToClosures2224251223/001/store/7zizqj2c2jfcdf84zbw51d6bpsnvasgy-a1634 URL: nar/02f0ggrasl6cmmcy6yqhfjr77ip21l2ws6ny1hxxpnpq719w870d.nar.zst1635 Compression: zstd1636 NarHash: sha256:02f0ggrasl6cmmcy6yqhfjr77ip21l2ws6ny1hxxpnpq719w870d1637 NarSize: 2561638 References: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientFallsBackToClosures2224251223/001/store/xqnwz3zgjwp509gx35pbv93cz0y6pph7-shared-dep16392026/11/01 17:51:19 INFO Completed push id=1 objects=3 duration=28.5035ms1640 CA: text:sha256:07386jk97lh1h5v6qsi9fac0qmvkq06gdffvhl085v9r9qsbsijv16412026/11/01 17:51:19 INFO Upload complete. (320ms)1642 client_pushes_test.go:112: Retrieved narinfo from S3:1643 StorePath: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientFallsBackToClosures2224251223/001/store/2c81za2xxy9lzgp4vc09n6qlflylmq72-b1644 URL: nar/02f0ggrasl6cmmcy6yqhfjr77ip21l2ws6ny1hxxpnpq719w870d.nar.zst1645 Compression: zstd1646 NarHash: sha256:02f0ggrasl6cmmcy6yqhfjr77ip21l2ws6ny1hxxpnpq719w870d1647 NarSize: 2561648 References: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientFallsBackToClosures2224251223/001/store/xqnwz3zgjwp509gx35pbv93cz0y6pph7-shared-dep1649 CA: text:sha256:07386jk97lh1h5v6qsi9fac0qmvkq06gdffvhl085v9r9qsbsijv1650--- PASS: TestClientFallsBackToClosures (8.51s)1651=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost16522026/11/01 17:51:19 INFO Received push request method=POST path=/api/pushes16532026/11/01 17:51:19 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)16542026/11/01 17:51:19 INFO Uploading cwfgdffqpn9m0rjmg6drigy9az8dgn3h-unpinned-file.txt (128B)16552026/11/01 17:51:19 WARN Failed to register uploaded object key=cwfgdffqpn9m0rjmg6drigy9az8dgn3h.ls error="server returned 404: 404 page not found\n"16562026/11/01 17:51:19 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign16572026/11/01 17:51:19 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"16582026/11/01 17:51:19 INFO Signed narinfos id=2 count=116592026/11/01 17:51:19 INFO Uploading 1 narinfos16602026/11/01 17:51:19 INFO Received complete push request method=POST path=/api/pushes/2/complete16612026/11/01 17:51:19 WARN Failed to register uploaded object key=cwfgdffqpn9m0rjmg6drigy9az8dgn3h.narinfo error="server returned 404: 404 page not found\n"16622026/11/01 17:51:19 INFO Completed push id=2 objects=3 duration=728.292µs16632026/11/01 17:51:19 INFO Upload complete. (197ms)16642026/11/01 17:51:19 INFO Starting cleanup of old closures method=DELETE path=/api/closures16652026/11/01 17:51:19 INFO Garbage collection started16662026/11/01 17:51:19 INFO Aborted multipart uploads count=0 kept=016672026/11/01 17:51:19 WARN Force mode enabled - objects will be deleted immediately without grace period16682026/11/01 17:51:19 INFO Received push request method=POST path=/api/pushes16692026/11/01 17:51:19 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)16702026/11/01 17:51:19 INFO Uploading m6i69afjj52m8ryfy0z68hrdqhwwfwdq-shared-dep (136B)16712026/11/01 17:51:19 INFO Uploading 7jxv2wlpf52vyqdapmzfha8bnq9ca0g9-b (256B)16722026/11/01 17:51:19 INFO lead: released remote=192.0.2.1:12341673--- PASS: TestLeadElectsOneAndHandsOver (10.68s)1674=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed16752026/11/01 17:51:19 WARN Failed to register uploaded object key=v0k84x17rfnfihhm6vli9hpwzisk9pxk.ls error="server returned 404: 404 page not found\n"16762026/11/01 17:51:19 WARN Failed to register uploaded object key=m6i69afjj52m8ryfy0z68hrdqhwwfwdq.ls error="server returned 404: 404 page not found\n"16772026/11/01 17:51:19 WARN Failed to register uploaded object key=7jxv2wlpf52vyqdapmzfha8bnq9ca0g9.ls error="server returned 404: 404 page not found\n"16782026/11/01 17:51:19 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16792026/11/01 17:51:19 WARN Failed to register uploaded object key=nar/1r5rfnkvvpnw5gafw6gi337cbr156bbln3cjm081xiiy062kc9a0.nar.zst error="server returned 404: 404 page not found\n"16802026/11/01 17:51:19 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign16812026/11/01 17:51:19 INFO Signed narinfos id=1 count=316822026/11/01 17:51:19 INFO Uploading 3 narinfos16832026/11/01 17:51:19 WARN Failed to register uploaded object key=m6i69afjj52m8ryfy0z68hrdqhwwfwdq.narinfo error="server returned 404: 404 page not found\n"16842026/11/01 17:51:19 WARN Failed to register uploaded object key=v0k84x17rfnfihhm6vli9hpwzisk9pxk.narinfo error="server returned 404: 404 page not found\n"16852026/11/01 17:51:19 INFO Received push request method=POST path=/api/pushes16862026/11/01 17:51:20 INFO Received complete push request method=POST path=/api/pushes/1/complete16872026/11/01 17:51:20 WARN Failed to register uploaded object key=7jxv2wlpf52vyqdapmzfha8bnq9ca0g9.narinfo error="server returned 404: 404 page not found\n"16882026/11/01 17:51:20 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)16892026/11/01 17:51:20 INFO Uploading jy4hnyb9pfrpx9rfmxb6ibmigp5rblsq-top (264B)16902026/11/01 17:51:20 INFO Uploading 4mn0vm3a50c6mxp9vqsv3x9vczi55nid-shared-dep (136B)16912026/11/01 17:51:20 INFO Completed push id=1 objects=8 duration=30.155375ms16922026/11/01 17:51:20 INFO Upload complete. (320ms)1693=== NAME TestClientPushesUseOnePush1694 client_pushes_test.go:97: Retrieved narinfo from S3:1695 StorePath: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientPushesUseOnePush3471182038/001/store/m6i69afjj52m8ryfy0z68hrdqhwwfwdq-shared-dep1696 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1697 Compression: zstd1698 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821699 NarSize: 1361700 References: 1701 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1702 client_pushes_test.go:97: Retrieved narinfo from S3:1703 StorePath: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientPushesUseOnePush3471182038/001/store/v0k84x17rfnfihhm6vli9hpwzisk9pxk-a1704 URL: nar/1r5rfnkvvpnw5gafw6gi337cbr156bbln3cjm081xiiy062kc9a0.nar.zst1705 Compression: zstd1706 NarHash: sha256:1r5rfnkvvpnw5gafw6gi337cbr156bbln3cjm081xiiy062kc9a01707 NarSize: 2561708 References: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientPushesUseOnePush3471182038/001/store/m6i69afjj52m8ryfy0z68hrdqhwwfwdq-shared-dep1709 CA: text:sha256:0zvca4fnd1r91pkdxc2sjgy0ciq5iv9d5yfd320xmg7gra47phpa17102026/11/01 17:51:20 WARN Failed to register uploaded object key=jy4hnyb9pfrpx9rfmxb6ibmigp5rblsq.ls error="server returned 404: 404 page not found\n"1711 client_pushes_test.go:97: Retrieved narinfo from S3:1712 StorePath: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientPushesUseOnePush3471182038/001/store/7jxv2wlpf52vyqdapmzfha8bnq9ca0g9-b1713 URL: nar/1r5rfnkvvpnw5gafw6gi337cbr156bbln3cjm081xiiy062kc9a0.nar.zst17142026/11/01 17:51:20 WARN Failed to register uploaded object key=4mn0vm3a50c6mxp9vqsv3x9vczi55nid.ls error="server returned 404: 404 page not found\n"1715 Compression: zstd17162026/11/01 17:51:20 WARN Failed to register uploaded object key=nar/0mgan3jrja69b758ry4143s1qk5b3ag2q2pg2dkjfry3arp60vwg.nar.zst error="server returned 404: 404 page not found\n"1717 NarHash: sha256:1r5rfnkvvpnw5gafw6gi337cbr156bbln3cjm081xiiy062kc9a01718 NarSize: 2561719 References: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientPushesUseOnePush3471182038/001/store/m6i69afjj52m8ryfy0z68hrdqhwwfwdq-shared-dep1720 CA: text:sha256:0zvca4fnd1r91pkdxc2sjgy0ciq5iv9d5yfd320xmg7gra47phpa17212026/11/01 17:51:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17222026/11/01 17:51:20 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"17232026/11/01 17:51:20 INFO Signed narinfos id=1 count=217242026/11/01 17:51:20 INFO Uploading 2 narinfos17252026/11/01 17:51:20 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=017262026/11/01 17:51:20 WARN Failed to register uploaded object key=4mn0vm3a50c6mxp9vqsv3x9vczi55nid.narinfo error="server returned 404: 404 page not found\n"17272026/11/01 17:51:20 INFO Received complete push request method=POST path=/api/pushes/1/complete17282026/11/01 17:51:20 WARN Failed to register uploaded object key=jy4hnyb9pfrpx9rfmxb6ibmigp5rblsq.narinfo error="server returned 404: 404 page not found\n"1729--- PASS: TestClientPushesUseOnePush (8.68s)1730=== CONT TestServerTLSConfig/no_client_CA1731=== CONT TestParseSingleRange/start_far_past_EOF1732=== CONT TestParseSingleRange/start_past_EOF1733=== CONT TestParseSingleRange/single_byte1734=== CONT TestParseSingleRange/suffix_exceeds_size1735=== NAME TestClientIntegration1736 client_integration_test.go:291: Created store path: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientIntegration2351008362/002/store/4381rjlrj4510yyw9ssdyqqnxzbpqa50-test-file.txt1737=== CONT TestParseSingleRange/suffix1738=== CONT TestParseSingleRange/end_clamped_to_size1739=== CONT TestParseSingleRange/open-ended1740=== CONT TestParseSingleRange/closed1741=== CONT TestParseSingleRange/malformed_end_before_start1742=== CONT TestParseSingleRange/malformed_both_empty1743=== CONT TestParseSingleRange/malformed_no_dash1744=== CONT TestParseSingleRange/multi-range_ignored1745=== CONT TestParseSingleRange/unknown_unit1746=== CONT TestProxyWriteTimeout/1_GiB_nar1747--- PASS: TestParseSingleRange (0.07s)1748 --- PASS: TestParseSingleRange/none (0.00s)1749 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1750 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1751 --- PASS: TestParseSingleRange/single_byte (0.00s)1752 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1753 --- PASS: TestParseSingleRange/suffix (0.00s)1754 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1755 --- PASS: TestParseSingleRange/open-ended (0.00s)1756 --- PASS: TestParseSingleRange/closed (0.00s)1757 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1758 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1759 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1760 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1761 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1762=== CONT TestProxyWriteTimeout/unknown_size1763=== CONT TestProxyWriteTimeout/10_GiB_nar1764=== CONT TestServerTLSConfig/not_a_PEM_file1765--- PASS: TestProxyWriteTimeout (0.07s)1766 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1767 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1768 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1769 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)17702026/11/01 17:51:20 INFO Completed push id=1 objects=6 duration=78.767416ms17712026/11/01 17:51:20 INFO Upload complete. (382ms)1772=== CONT TestServerTLSConfig/missing_CA_file1773--- PASS: TestServerTLSConfig (0.00s)1774 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1775 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)1776 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1777=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17782026/11/01 17:51:20 INFO Received uploads request method=POST path=/1779=== NAME TestClientSharedPathCommittedMidPush1780 client_integration_test.go:727: Retrieved narinfo from S3:1781 StorePath: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientSharedPathCommittedMidPush1918303175/001/store/4mn0vm3a50c6mxp9vqsv3x9vczi55nid-shared-dep1782 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1783 Compression: zstd1784 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821785 NarSize: 1361786 References: 1787 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n17882026/11/01 17:51:20 INFO Vacuumed table table=pending_closures1789 client_integration_test.go:727: Retrieved narinfo from S3:1790 StorePath: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientSharedPathCommittedMidPush1918303175/001/store/jy4hnyb9pfrpx9rfmxb6ibmigp5rblsq-top1791 URL: nar/0mgan3jrja69b758ry4143s1qk5b3ag2q2pg2dkjfry3arp60vwg.nar.zst1792 Compression: zstd1793 NarHash: sha256:0mgan3jrja69b758ry4143s1qk5b3ag2q2pg2dkjfry3arp60vwg1794 NarSize: 2641795 References: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientSharedPathCommittedMidPush1918303175/001/store/4mn0vm3a50c6mxp9vqsv3x9vczi55nid-shared-dep1796 CA: text:sha256:1b23icss2vj4innfrglkp2mgs1c5p96w4p7qchspkzglkspqg59b17972026/11/01 17:51:20 INFO Vacuumed table table=pending_objects17982026/11/01 17:51:20 INFO Vacuumed table table=multipart_uploads17992026/11/01 17:51:20 INFO Vacuumed table table=closures18002026/11/01 17:51:20 INFO Vacuumed table table=objects1801--- PASS: TestClientSharedPathCommittedMidPush (8.58s)1802=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18032026/11/01 17:51:20 INFO Received request for more parts method=POST path=/18042026/11/01 17:51:20 INFO Received push request method=POST path=/api/pushes1805=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18062026/11/01 17:51:20 INFO Received complete multipart upload request method=POST path=/18072026/11/01 17:51:20 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18082026/11/01 17:51:20 INFO Uploading 4381rjlrj4510yyw9ssdyqqnxzbpqa50-test-file.txt (152B)1809=== CONT TestPush_RejectsBadRequests/no_roots18102026/11/01 17:51:20 INFO Received push request method=POST path=/api/pushes1811=== NAME TestClientMultipleUploads1812 client_integration_test.go:405: Created store path 0: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientMultipleUploads156354415/001/store/xd2bkvd39zixpdpc5l08qg5kmlp4jri1-test-file-0.txt18132026/11/01 17:51:20 WARN Failed to register uploaded object key=4381rjlrj4510yyw9ssdyqqnxzbpqa50.ls error="server returned 404: 404 page not found\n"1814=== CONT TestPush_RejectsBadRequests/bad_root18152026/11/01 17:51:20 INFO Received push request method=POST path=/api/pushes1816=== CONT TestPush_RejectsBadRequests/root_not_in_objects18172026/11/01 17:51:20 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18182026/11/01 17:51:20 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18192026/11/01 17:51:20 INFO Received push request method=POST path=/api/pushes1820=== CONT TestPush_RejectsBadRequests/no_objects18212026/11/01 17:51:20 INFO Received push request method=POST path=/api/pushes1822=== CONT TestGCEndsOnShutdown/before_the_run1823--- PASS: TestPush_RejectsBadRequests (2.01s)1824 --- PASS: TestPush_RejectsBadRequests/no_roots (0.01s)1825 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1826 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1827 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)18282026/11/01 17:51:20 INFO Signed narinfos id=1 count=118292026/11/01 17:51:20 INFO Uploading 1 narinfos1830--- PASS: TestCacheStatsHandler (7.07s)1831=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark18322026/11/01 17:51:20 INFO Received complete push request method=POST path=/api/pushes/1/complete18332026/11/01 17:51:20 WARN Failed to register uploaded object key=4381rjlrj4510yyw9ssdyqqnxzbpqa50.narinfo error="server returned 404: 404 page not found\n"18342026/11/01 17:51:20 INFO Completed push id=1 objects=3 duration=24.515375ms18352026/11/01 17:51:20 INFO Upload complete. (303ms)1836=== NAME TestClientMultipleUploads1837 client_integration_test.go:405: Created store path 1: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientMultipleUploads156354415/001/store/mbqfh40da0j44nkcym4p1kqqc0slmq76-test-file-1.txt18382026/11/01 17:51:20 INFO All 1 paths already cached1839=== NAME TestClientIntegration1840 client_integration_test.go:317: Retrieved narinfo from S3:1841 StorePath: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientIntegration2351008362/002/store/4381rjlrj4510yyw9ssdyqqnxzbpqa50-test-file.txt1842 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1843 Compression: zstd1844 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11845 NarSize: 1521846 References: 1847 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11848 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1849 client_integration_test.go:318: Decompressed .ls content (64 bytes):1850 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}1851--- PASS: TestUploadHandlersRejectOversizedBody (0.16s)1852 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.07s)1853 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.06s)1854 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.46s)1855=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1856=== NAME TestClientMultipleUploads1857 client_integration_test.go:405: Created store path 2: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientMultipleUploads156354415/001/store/s15jhas810i7pqx9w4wxfq7d2dlz66m1-test-file-2.txt18582026/11/01 17:51:20 INFO Received push request method=POST path=/api/pushes18592026/11/01 17:51:20 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18602026/11/01 17:51:20 INFO Uploading xd2bkvd39zixpdpc5l08qg5kmlp4jri1-test-file-0.txt (160B)18612026/11/01 17:51:20 INFO Uploading mbqfh40da0j44nkcym4p1kqqc0slmq76-test-file-1.txt (160B)18622026/11/01 17:51:20 INFO Uploading s15jhas810i7pqx9w4wxfq7d2dlz66m1-test-file-2.txt (160B)18632026/11/01 17:51:20 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18642026/11/01 17:51:20 WARN Failed to register uploaded object key=mbqfh40da0j44nkcym4p1kqqc0slmq76.ls error="server returned 404: 404 page not found\n"18652026/11/01 17:51:20 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18662026/11/01 17:51:20 WARN Failed to register uploaded object key=s15jhas810i7pqx9w4wxfq7d2dlz66m1.ls error="server returned 404: 404 page not found\n"18672026/11/01 17:51:20 INFO Received push request method=POST path=/api/pushes18682026/11/01 17:51:21 INFO Object in database but missing from S3 key=4381rjlrj4510yyw9ssdyqqnxzbpqa50.ls18692026/11/01 17:51:21 WARN Found objects in DB but missing from S3, will re-upload count=118702026/11/01 17:51:21 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18712026/11/01 17:51:21 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)18722026/11/01 17:51:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18732026/11/01 17:51:21 WARN Failed to register uploaded object key=xd2bkvd39zixpdpc5l08qg5kmlp4jri1.ls error="server returned 404: 404 page not found\n"18742026/11/01 17:51:21 INFO Signed narinfos id=1 count=318752026/11/01 17:51:21 INFO Uploading 3 narinfos18762026/11/01 17:51:21 WARN Failed to register uploaded object key=s15jhas810i7pqx9w4wxfq7d2dlz66m1.narinfo error="server returned 404: 404 page not found\n"18772026/11/01 17:51:21 INFO Received complete push request method=POST path=/api/pushes/2/complete18782026/11/01 17:51:21 WARN Failed to register uploaded object key=4381rjlrj4510yyw9ssdyqqnxzbpqa50.ls error="server returned 404: 404 page not found\n"18792026/11/01 17:51:21 WARN Failed to register uploaded object key=xd2bkvd39zixpdpc5l08qg5kmlp4jri1.narinfo error="server returned 404: 404 page not found\n"18802026/11/01 17:51:21 INFO Completed push id=2 objects=3 duration=752.25µs18812026/11/01 17:51:21 INFO Upload complete. (181ms)18822026/11/01 17:51:21 INFO Received complete push request method=POST path=/api/pushes/1/complete18832026/11/01 17:51:21 WARN Failed to register uploaded object key=mbqfh40da0j44nkcym4p1kqqc0slmq76.narinfo error="server returned 404: 404 page not found\n"1884=== NAME TestClientIntegration1885 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1886 client_integration_test.go:335: Decompressed .ls content (49 bytes):1887 {"version":1,"root":{"type":"regular","size":39}}1888=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1889=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1890=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1891=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1892=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1893=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1894=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1895=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1896=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows18972026/11/01 17:51:21 INFO Completed push id=1 objects=9 duration=31.642291ms18982026/11/01 17:51:21 INFO Upload complete. (338ms)1899=== NAME TestClientMultipleUploads1900 client_integration_test.go:416: Uploaded 3 paths in 372.646791ms1901--- PASS: TestClientMultipleUploads (9.36s)1902=== CONT TestIsValidCachePath/narinfo1903=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check19042026/11/01 17:51:21 INFO Received push request method=POST path=/api/pushes19052026/11/01 17:51:21 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1906=== NAME TestClientCADerivations1907 client_ca_test.go:136: Built CA derivation: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientCADerivations1945741737/001/store/s0jgc8srk7ph9dxrdz3463wqwb63nzxs-ca-test1908--- PASS: TestService_ReadScope_PublicByDefault (7.06s)1909=== CONT TestIsValidCachePath/index.html1910=== CONT TestIsValidCachePath/short_hash1911=== CONT TestIsValidCachePath/wrong_extension1912=== CONT TestIsValidCachePath/leading_slash1913=== CONT TestIsValidCachePath/empty1914=== CONT TestIsValidCachePath/random_path1915=== CONT TestIsValidCachePath/invalid_char_u1916=== CONT TestIsValidCachePath/invalid_char_e1917=== CONT TestIsValidCachePath/traversal_in_middle1918=== CONT TestIsValidCachePath/traversal_parent1919=== CONT TestIsValidCachePath/nar_uncompressed1920=== CONT TestIsValidCachePath/nix-cache-info1921=== CONT TestIsValidCachePath/realisation1922=== CONT TestIsValidCachePath/log1923=== CONT TestIsValidCachePath/ls1924=== CONT TestIsValidCachePath/nar_xz1925=== CONT TestIsValidCachePath/nar_bz21926=== CONT TestIsValidCachePath/nar_zst1927=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1928--- PASS: TestIsValidCachePath (0.00s)1929 --- PASS: TestIsValidCachePath/narinfo (0.00s)1930 --- PASS: TestIsValidCachePath/index.html (0.00s)1931 --- PASS: TestIsValidCachePath/short_hash (0.00s)1932 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1933 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1934 --- PASS: TestIsValidCachePath/empty (0.00s)1935 --- PASS: TestIsValidCachePath/random_path (0.00s)1936 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1937 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1938 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1939 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1940 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1941 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1942 --- PASS: TestIsValidCachePath/realisation (0.00s)1943 --- PASS: TestIsValidCachePath/log (0.00s)1944 --- PASS: TestIsValidCachePath/ls (0.00s)1945 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1946 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1947 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1948 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)19492026/11/01 17:51:21 INFO Received complete push request method=POST path=/api/pushes/3/complete1950=== CONT TestResolveDBConnectionString/flag_wins1951=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1952=== CONT TestResolveDBConnectionString/nothing_configured1953=== CONT TestResolveDBConnectionString/missing_file_is_an_error1954=== CONT TestResolveDBConnectionString/file_when_flag_empty19552026/11/01 17:51:21 WARN Failed to register uploaded object key=4381rjlrj4510yyw9ssdyqqnxzbpqa50.ls error="server returned 404: 404 page not found\n"19562026/11/01 17:51:21 INFO Completed push id=3 objects=3 duration=994.958µs1957=== CONT TestCacheConfigHandler/full_config,_no_issuer19582026/11/01 17:51:21 INFO Upload complete. (112ms)1959=== CONT TestCacheConfigHandler/no_signing_keys1960=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1961--- PASS: TestResolveDBConnectionString (0.03s)1962 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1963 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1964 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1965 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1966 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1967=== NAME TestClientIntegration1968 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1969=== CONT TestCacheConfigHandler/no_cache_url_configured1970--- PASS: TestCacheConfigHandler (0.01s)1971 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1972 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1973 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1974 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)1975=== CONT TestClientErrorHandling/InvalidStorePath1976=== NAME TestClientIntegration1977 client_integration_test.go:352: Decompressed .ls content (49 bytes):1978 {"version":1,"root":{"type":"regular","size":39}}1979 client_integration_test.go:363: Testing garbage collection...1980=== NAME TestClientCADerivations1981 client_ca_test.go:139: Found 1 dependencies (including self)19822026/11/01 17:51:21 INFO Starting cleanup of old closures method=DELETE path=/api/closures19832026/11/01 17:51:21 INFO Garbage collection started19842026/11/01 17:51:21 INFO Aborted multipart uploads count=0 kept=019852026/11/01 17:51:21 WARN Force mode enabled - objects will be deleted immediately without grace period19862026/11/01 17:51:21 INFO Received push request method=POST path=/api/pushes19872026/11/01 17:51:21 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19882026/11/01 17:51:21 INFO Uploading s0jgc8srk7ph9dxrdz3463wqwb63nzxs-ca-test (144B)19892026/11/01 17:51:21 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=019902026/11/01 17:51:21 INFO Received create pin request method=POST path=/api/pins/myapp1991=== RUN TestService_RequireScope_OIDC/builder_may_write1992=== PAUSE TestService_RequireScope_OIDC/builder_may_write1993=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1994=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin19952026/11/01 17:51:21 WARN Failed to register uploaded object key=s0jgc8srk7ph9dxrdz3463wqwb63nzxs.ls error="server returned 404: 404 page not found\n"19962026/11/01 17:51:21 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"1997=== RUN TestService_RequireScope_OIDC/ops_may_admin1998=== PAUSE TestService_RequireScope_OIDC/ops_may_admin19992026/11/01 17:51:21 WARN Failed to register uploaded object key=log/xq4k9m26yspnz57ki5a9hv62y07ygmlf-ca-test.drv error="server returned 404: 404 page not found\n"2000=== RUN TestService_RequireScope_OIDC/ops_may_not_write20012026/11/01 17:51:21 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign2002=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write20032026/11/01 17:51:21 INFO Signed narinfos id=1 count=12004=== RUN TestService_RequireScope_OIDC/reader_may_not_write2005=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write20062026/11/01 17:51:21 INFO Created/updated pin name=myapp store_path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestPinProtectsFromGC4146695739/001/store/n4975kfynf85gwnbdbx41f6vgrih047r-pinned-file.txt narinfo_key=n4975kfynf85gwnbdbx41f6vgrih047r.narinfo2007=== RUN TestService_RequireScope_OIDC/static_token_may_admin20082026/11/01 17:51:21 INFO Uploading 1 narinfos2009=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2010=== RUN TestService_RequireScope_OIDC/static_token_may_write2011=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2012=== RUN TestService_RequireScope_OIDC/reader_may_read2013=== PAUSE TestService_RequireScope_OIDC/reader_may_read2014=== RUN TestService_RequireScope_OIDC/writer_implies_read2015=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2016=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2017=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2018=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc2019=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc2020=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2021=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2022=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2023=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2024=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2025=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2026=== CONT TestClientErrorHandling/ServerNotAvailable20272026/11/01 17:51:21 INFO Starting cleanup of old closures method=DELETE path=/api/closures20282026/11/01 17:51:21 INFO Garbage collection started20292026/11/01 17:51:21 INFO Aborted multipart uploads count=0 kept=020302026/11/01 17:51:21 WARN Force mode enabled - objects will be deleted immediately without grace period20312026/11/01 17:51:21 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=020322026/11/01 17:51:21 INFO Vacuumed table table=pending_closures20332026/11/01 17:51:21 INFO Vacuumed table table=pending_objects20342026/11/01 17:51:21 INFO Vacuumed table table=multipart_uploads20352026/11/01 17:51:21 INFO Vacuumed table table=closures20362026/11/01 17:51:21 INFO Vacuumed table table=objects20372026/11/01 17:51:21 INFO Received complete push request method=POST path=/api/pushes/1/complete20382026/11/01 17:51:21 WARN Failed to register uploaded object key=s0jgc8srk7ph9dxrdz3463wqwb63nzxs.narinfo error="server returned 404: 404 page not found\n"20392026/11/01 17:51:21 INFO Completed push id=1 objects=4 duration=60.425666ms20402026/11/01 17:51:21 INFO Upload complete. (433ms)2041=== NAME TestClientCADerivations2042 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientCADerivations1945741737/001/store/s0jgc8srk7ph9dxrdz3463wqwb63nzxs-ca-test2043 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst2044 Compression: zstd2045 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2046 NarSize: 1442047 References: 2048 Deriver: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientCADerivations1945741737/001/store/xq4k9m26yspnz57ki5a9hv62y07ygmlf-ca-test.drv2049 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n2050 client_ca_test.go:185: Checking for realisation files in S3...2051 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations2052 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache20532026/11/01 17:51:22 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=020542026/11/01 17:51:22 INFO Vacuumed table table=pending_closures20552026/11/01 17:51:22 INFO Vacuumed table table=pending_objects20562026/11/01 17:51:22 INFO Vacuumed table table=multipart_uploads2057 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket83?endpoint=http://localhost:55286®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestClientCADerivations1945741737/001/store'2058 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 120592026/11/01 17:51:22 INFO Vacuumed table table=closures20602026/11/01 17:51:22 INFO Vacuumed table table=objects20612026/11/01 17:51:22 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"20622026/11/01 17:51:22 WARN mTLS auth: bound subjects configured but subject DN unavailable20632026/11/01 17:51:22 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2064--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (7.53s)2065=== CONT TestClientErrorHandling/InvalidAuthToken2066--- PASS: TestClientCADerivations (9.48s)2067=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2068=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20692026/11/01 17:51:22 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]2070=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2071=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20722026/11/01 17:51:22 WARN Authentication failed token_preview=eyJhbGciOi...1T31ZBLseQ token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2073=== CONT TestService_RequireScope_OIDC/builder_may_write20742026/11/01 17:51:22 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/present2075=== CONT TestService_RequireScope_OIDC/reader_may_read2076=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2077=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read20782026/11/01 17:51:22 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]2079=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2080=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc2081=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2082=== CONT TestService_RequireScope_OIDC/writer_implies_read2083=== CONT TestService_RequireScope_OIDC/reader_may_not_write2084=== CONT TestService_RequireScope_OIDC/static_token_may_write2085--- PASS: TestService_AuthMiddleware_OIDC (7.65s)2086 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2087 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.01s)2088 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2089 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2090=== CONT TestService_RequireScope_OIDC/static_token_may_admin2091=== CONT TestService_RequireScope_OIDC/ops_may_admin2092=== CONT TestService_RequireScope_OIDC/ops_may_not_write2093=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2094--- PASS: TestService_RequireScope_OIDC (6.93s)2095 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2096 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2097 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2098 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)2099 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2100 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)2101 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2102 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2103 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2104 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2105 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2106 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2107 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2108 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)21092026/11/01 17:51:22 WARN Request failed, retrying attempt=2 backoff=185.737071ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21102026/11/01 17:51:23 WARN Request failed, retrying attempt=3 backoff=437.635601ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21112026/11/01 17:51:23 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02112=== NAME TestClientIntegration2113 client_integration_test.go:370: Objects in database after GC:2114 client_integration_test.go:370: Successfully deleted all objects with GC --force21152026/11/01 17:51:23 WARN Request failed, retrying attempt=4 backoff=851.506408ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2116--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (8.26s)2117=== NAME TestPinProtectsFromGC2118 client_integration_test.go:887: Pin successfully protected closure from garbage collection2119--- PASS: TestClientIntegration (11.65s)2120--- PASS: TestPinProtectsFromGC (12.59s)21212026/11/01 17:51:24 WARN Request failed, retrying attempt=5 backoff=1.726461474s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2122--- PASS: TestService_ReadAuthMiddleware (9.24s)2123--- PASS: TestDeleteClosuresRacingPins (15.54s)21242026/11/01 17:51:25 INFO Aborted multipart uploads count=0 kept=021252026/11/01 17:51:25 WARN Force mode enabled - objects will be deleted immediately without grace period21262026/11/01 17:51:25 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=021272026/11/01 17:51:25 INFO Vacuumed table table=pending_closures21282026/11/01 17:51:26 INFO Vacuumed table table=pending_objects21292026/11/01 17:51:26 INFO Vacuumed table table=multipart_uploads21302026/11/01 17:51:26 INFO Vacuumed table table=closures21312026/11/01 17:51:26 INFO Vacuumed table table=objects2132--- PASS: TestCommitRacingPendingCleanupKeepsObjects (9.71s)21332026/11/01 17:51:26 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-config21342026/11/01 17:51:26 WARN Request failed, retrying attempt=2 backoff=215.497969ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21352026/11/01 17:51:26 WARN Request failed, retrying attempt=3 backoff=411.709229ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21362026/11/01 17:51:27 WARN Request failed, retrying attempt=4 backoff=872.252482ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21372026/11/01 17:51:27 INFO Received uploads request method=POST path=/api/pending_closures2138=== NAME TestOrphanedObjectsGCStressTest2139 orphaned_objects_gc_test.go:503: Stress test completed successfully:2140 orphaned_objects_gc_test.go:504: - Active objects preserved: 202141 orphaned_objects_gc_test.go:505: - Objects deleted: 2102142 orphaned_objects_gc_test.go:506: - Total GC'd: 2102143--- PASS: TestOrphanedObjectsGCStressTest (35.18s)21442026/11/01 17:51:27 WARN Request failed, retrying attempt=5 backoff=1.700842168s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21452026/11/01 17:51:28 INFO Received uploads request method=POST path=/api/pending_closures2146--- PASS: TestPendingClosureWriteTimeout (0.06s)2147 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2148 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2149 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2150 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (11.09s)2151--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.06s)2152 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (10.46s)2153 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (10.88s)21542026/11/01 17:51:28 INFO Received uploads request method=POST path=/api/pending_closures21552026/11/01 17:51:28 INFO Received uploads request method=POST path=/api/pending_closures21562026/11/01 17:51:29 INFO Received uploads request method=POST path=/api/pending_closures21572026/11/01 17:51:29 INFO Received uploads request method=POST path=/api/pending_closures21582026/11/01 17:51:29 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"21592026/11/01 17:51:29 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-config21602026/11/01 17:51:29 WARN Request failed, retrying attempt=2 backoff=205.218527ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21612026/11/01 17:51:29 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21622026/11/01 17:51:30 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LjVmMDBiN2QwLTBiYzMtNDAyMC04MjlkLTIzOWQzYWY0ZTg2NXgxNzkzNTU1NDg4Mzc1MDEwMDAw parts=1021632026/11/01 17:51:30 WARN Request failed, retrying attempt=3 backoff=404.540574ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21642026/11/01 17:51:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21652026/11/01 17:51:30 INFO Completed upload id=1 objects=3 duration=15.321166ms21662026/11/01 17:51:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21672026/11/01 17:51:30 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LjE4OWI5ZjgzLTFjYzMtNGIzNC04YTlkLWExNWIzNzhlM2JkOXgxNzkzNTU1NDg4NjE2MDcwMDAw parts=1021682026/11/01 17:51:30 INFO Aborted multipart uploads count=0 kept=021692026/11/01 17:51:30 WARN Force mode enabled - objects will be deleted immediately without grace period21702026-11-01 17:51:30.413 UTC [30225] ERROR: canceling statement due to user request21712026-11-01 17:51:30.413 UTC [30225] STATEMENT: -- name: MarkStaleObjects :execrows2172 WITH RECURSIVE ct AS (2173 SELECT timezone('UTC', now()) AS now2174 ),2175 closure_reach AS (2176 -- Start with all closure keys2177 SELECT o.key, o.refs2178 FROM objects o2179 INNER JOIN closures c ON o.key = c.key2180 UNION2181 -- Recursively add all referenced objects2182 SELECT o.key, o.refs2183 FROM objects o2184 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2185 ),2186 reachable_objects AS (2187 SELECT DISTINCT key FROM closure_reach2188 ),2189 stale_objects AS (2190 SELECT o.key2191 FROM objects AS o, ct2192 WHERE2193 NOT EXISTS (2194 SELECT 12195 FROM reachable_objects ro2196 WHERE ro.key = o.key2197 )2198 AND NOT EXISTS (2199 SELECT 12200 FROM pending_objects AS po2201 WHERE po.key = o.key2202 )2203 AND o.deleted_at IS NULL -- Only mark fresh objects2204 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2205 FOR UPDATE2206 )2207 UPDATE objects2208 SET2209 deleted_at = ct.now,2210 first_deleted_at = COALESCE(first_deleted_at, ct.now)2211 FROM stale_objects, ct2212 WHERE objects.key = stale_objects.key2213 22142026/11/01 17:51:30 WARN Request failed, retrying attempt=4 backoff=789.380126ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22152026/11/01 17:51:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22162026/11/01 17:51:30 INFO Completed upload id=1 objects=3 duration=21.726417ms22172026/11/01 17:51:30 INFO Received uploads request method=POST path=/api/pending_closures22182026/11/01 17:51:30 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst22192026/11/01 17:51:30 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo22202026/11/01 17:51:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22212026/11/01 17:51:30 INFO Aborted multipart uploads count=0 kept=022222026/11/01 17:51:30 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LjQ5OTRjYWJjLWQ1ZDItNGE2Ny1hYzExLWNmMmQzOWM0NWE2NXgxNzkzNTU1NDg4OTA4Njk0MDAw parts=1022232026/11/01 17:51:30 WARN Force mode enabled - objects will be deleted immediately without grace period22242026/11/01 17:51:30 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:55286/bucket101/?delete=\": context canceled"2225--- PASS: TestGCEndsOnShutdown (0.00s)2226 --- PASS: TestGCEndsOnShutdown/before_the_run (9.47s)2227 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (9.88s)2228 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (10.05s)22292026/11/01 17:51:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22302026/11/01 17:51:30 INFO Completed upload id=1 objects=3 duration=11.815458ms22312026/11/01 17:51:30 INFO Received uploads request method=POST path=/api/pending_closures22322026/11/01 17:51:30 INFO Received uploads request method=POST path=/api/pending_closures22332026/11/01 17:51:30 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22342026/11/01 17:51:30 WARN Found objects in DB but missing from S3, will re-upload count=122352026/11/01 17:51:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22362026/11/01 17:51:31 INFO Received uploads request method=POST path=/api/pending_closures22372026/11/01 17:51:31 INFO Aborted multipart uploads count=0 kept=022382026/11/01 17:51:31 WARN Force mode enabled - objects will be deleted immediately without grace period22392026/11/01 17:51:31 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LmVhNGFiZWRhLWQzYmEtNGU1ZS04MTM2LTc0NGUwZDNlY2U0M3gxNzkzNTU1NDg5MjMxODQ2MDAw parts=1022402026/11/01 17:51:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22412026/11/01 17:51:31 INFO Completed upload id=1 objects=3 duration=9.65175ms22422026/11/01 17:51:31 INFO Received uploads request method=POST path=/api/pending_closures22432026/11/01 17:51:31 WARN Request failed, retrying attempt=5 backoff=1.530079962s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22442026/11/01 17:51:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22452026/11/01 17:51:31 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=022462026/11/01 17:51:31 INFO Vacuumed table table=pending_closures22472026/11/01 17:51:31 INFO Vacuumed table table=pending_objects22482026/11/01 17:51:31 INFO Vacuumed table table=multipart_uploads22492026/11/01 17:51:31 INFO Vacuumed table table=closures22502026/11/01 17:51:31 INFO Vacuumed table table=objects22512026/11/01 17:51:31 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LmJkMmM2MjRmLTU3MmItNDJhNS05YjQxLThlNzJiZWUxMTQ2MXgxNzkzNTU1NDg5NTU0MzgxMDAw parts=1022522026/11/01 17:51:31 INFO Received uploads request method=POST path=/api/pending_closures22532026/11/01 17:51:31 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22542026/11/01 17:51:31 INFO Aborted multipart uploads count=0 kept=022552026/11/01 17:51:31 INFO Completed upload id=1 objects=3 duration=12.932542ms22562026/11/01 17:51:31 INFO Received uploads request method=POST path=/api/pending_closures22572026/11/01 17:51:31 WARN Force mode enabled - objects will be deleted immediately without grace period22582026/11/01 17:51:31 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=022592026/11/01 17:51:31 INFO Vacuumed table table=pending_closures22602026/11/01 17:51:31 INFO Vacuumed table table=pending_objects22612026/11/01 17:51:31 INFO Vacuumed table table=multipart_uploads22622026/11/01 17:51:31 INFO Vacuumed table table=closures22632026/11/01 17:51:31 INFO Vacuumed table table=objects2264--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2265 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (10.46s)2266 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (10.39s)22672026/11/01 17:51:32 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22682026/11/01 17:51:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22692026/11/01 17:51:32 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22702026/11/01 17:51:32 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1LmQ1OTkyODk2LWI0ZTktNDlmZi1hNGZjLTA5YmYxNDQ5MzQ2NHgxNzkzNTU1NDkwODI5Njk1MDAw parts=1022712026/11/01 17:51:32 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22722026/11/01 17:51:32 INFO Completed upload id=2 objects=3 duration=334.834µs22732026/11/01 17:51:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22742026/11/01 17:51:32 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=YjlkNTAxZDgtMTQwZC00NGQyLTljOGMtMWM1OWQ2YWVlYzY1Ljc0OGYzNWY1LTNkYjEtNDBiMS1hNjBjLTY0YWM3MjQxODRhYngxNzkzNTU1NDkxMjE4MDI2MDAw parts=1022752026/11/01 17:51:32 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22762026/11/01 17:51:32 INFO Completed upload id=2 objects=3 duration=1.031917ms22772026/11/01 17:51:32 INFO Received uploads request method=POST path=/api/pending_closures22782026/11/01 17:51:32 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22792026/11/01 17:51:32 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22802026/11/01 17:51:32 INFO Received uploads request method=POST path=/api/pending_closures22812026/11/01 17:51:32 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22822026/11/01 17:51:32 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2283--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.07s)2284 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (12.35s)2285 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (12.38s)2286 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (11.71s)2287 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (13.35s)2288 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (13.15s)22892026/11/01 17:51:32 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_closures22902026/11/01 17:51:32 WARN Request failed, retrying attempt=2 backoff=212.422425ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22912026/11/01 17:51:33 WARN Request failed, retrying attempt=3 backoff=423.004943ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22922026/11/01 17:51:33 WARN Request failed, retrying attempt=4 backoff=848.518584ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22932026/11/01 17:51:34 WARN Request failed, retrying attempt=5 backoff=1.642694618s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2294--- PASS: TestClientErrorHandling (0.03s)2295 --- PASS: TestClientErrorHandling/InvalidStorePath (10.29s)2296 --- PASS: TestClientErrorHandling/InvalidAuthToken (9.50s)2297 --- PASS: TestClientErrorHandling/ServerNotAvailable (14.21s)2298PASS2299{"timestamp":"2026-11-01T17:51:36.015302Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55785","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)"}2300{"timestamp":"2026-11-01T17:51:36.015367Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55676","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(11)"}2301{"timestamp":"2026-11-01T17:51:36.018029Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55677","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)"}2302{"timestamp":"2026-11-01T17:51:36.015237Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:55794","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)"}23032026-11-01 17:51:36.153 UTC [29733] LOG: received smart shutdown request23042026-11-01 17:51:36.154 UTC [29733] LOG: background worker "logical replication launcher" (PID 29743) exited with exit code 123052026-11-01 17:51:36.160 UTC [29738] LOG: shutting down23062026-11-01 17:51:36.160 UTC [29738] LOG: checkpoint starting: shutdown immediate23072026-11-01 17:51:37.805 UTC [29738] LOG: checkpoint complete: wrote 12150 buffers (74.2%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.910 s, sync=0.704 s, total=1.645 s; sync files=35725, longest=0.001 s, average=0.001 s; distance=525299 kB, estimate=525299 kB; lsn=0/21889BC8, redo lsn=0/21889BC823082026-11-01 17:51:37.813 UTC [29733] LOG: database system is shut down2309Running OIDC tests...2310=== RUN TestAudienceForIssuer2311=== PAUSE TestAudienceForIssuer2312=== RUN TestGlobMatch2313=== PAUSE TestGlobMatch2314=== RUN TestValidateToken_ValidToken2315=== PAUSE TestValidateToken_ValidToken2316=== RUN TestValidateToken_WrongAudience2317=== PAUSE TestValidateToken_WrongAudience2318=== RUN TestValidateToken_Expired2319=== PAUSE TestValidateToken_Expired2320=== RUN TestValidateToken_BoundClaimsMismatch2321=== PAUSE TestValidateToken_BoundClaimsMismatch2322=== RUN TestValidateToken_BoundSubjectMismatch2323=== PAUSE TestValidateToken_BoundSubjectMismatch2324=== RUN TestValidateToken_MultipleProviders2325=== PAUSE TestValidateToken_MultipleProviders2326=== RUN TestValidateToken_NoMatchingProvider2327=== PAUSE TestValidateToken_NoMatchingProvider2328=== RUN TestValidateToken_KubernetesServiceAccount2329=== PAUSE TestValidateToken_KubernetesServiceAccount2330=== RUN TestNewValidator_KubernetesRequiresCA2331=== PAUSE TestNewValidator_KubernetesRequiresCA2332=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2333=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2334=== RUN TestPins_ReservedForMatchingRule2335=== PAUSE TestPins_ReservedForMatchingRule2336=== RUN TestPins_TopLevelShorthand2337=== PAUSE TestPins_TopLevelShorthand2338=== RUN TestPins_ConfigValidation2339=== PAUSE TestPins_ConfigValidation2340=== RUN TestScopes_LegacyProviderDefaultsToWrite2341=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2342=== RUN TestScopes_Rules2343=== PAUSE TestScopes_Rules2344=== RUN TestScopes_ConfigValidation2345=== PAUSE TestScopes_ConfigValidation2346=== CONT TestAudienceForIssuer2347--- PASS: TestAudienceForIssuer (0.00s)2348=== CONT TestPins_ConfigValidation2349=== CONT TestNewValidator_KubernetesRequiresCA2350=== CONT TestScopes_Rules2351=== CONT TestValidateToken_KubernetesServiceAccount2352=== CONT TestValidateToken_NoMatchingProvider2353=== CONT TestValidateToken_MultipleProviders2354=== CONT TestValidateToken_BoundSubjectMismatch2355--- PASS: TestPins_ConfigValidation (0.00s)2356=== CONT TestValidateToken_BoundClaimsMismatch2357=== CONT TestValidateToken_Expired2358=== CONT TestValidateToken_WrongAudience2359=== CONT TestValidateToken_ValidToken2360=== CONT TestGlobMatch2361=== RUN TestGlobMatch/foo_foo2362=== PAUSE TestGlobMatch/foo_foo2363=== RUN TestGlobMatch/foo_bar2364=== PAUSE TestGlobMatch/foo_bar2365=== RUN TestGlobMatch/*_2366=== PAUSE TestGlobMatch/*_2367=== RUN TestGlobMatch/*_anything2368=== PAUSE TestGlobMatch/*_anything2369=== RUN TestGlobMatch/foo*_foo2370=== PAUSE TestGlobMatch/foo*_foo2371=== RUN TestGlobMatch/foo*_foobar2372=== PAUSE TestGlobMatch/foo*_foobar2373=== RUN TestGlobMatch/foo*_bar2374=== PAUSE TestGlobMatch/foo*_bar2375=== RUN TestGlobMatch/*bar_bar2376=== PAUSE TestGlobMatch/*bar_bar2377=== RUN TestGlobMatch/*bar_foobar2378=== PAUSE TestGlobMatch/*bar_foobar2379=== RUN TestGlobMatch/*bar_foo2380=== PAUSE TestGlobMatch/*bar_foo2381=== RUN TestGlobMatch/foo*bar_foobar2382=== PAUSE TestGlobMatch/foo*bar_foobar2383=== RUN TestGlobMatch/foo*bar_foo123bar2384=== PAUSE TestGlobMatch/foo*bar_foo123bar2385=== RUN TestGlobMatch/foo*bar_foobarbaz2386=== PAUSE TestGlobMatch/foo*bar_foobarbaz2387=== RUN TestGlobMatch/*/*_foo/bar2388=== PAUSE TestGlobMatch/*/*_foo/bar2389=== RUN TestGlobMatch/*/*_foo2390=== PAUSE TestGlobMatch/*/*_foo2391=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2392=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2393=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02394=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02395=== RUN TestGlobMatch/refs/*/main_refs/heads/main2396=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2397=== RUN TestGlobMatch/fo?_foo2398=== PAUSE TestGlobMatch/fo?_foo2399=== RUN TestGlobMatch/fo?_fo2400=== PAUSE TestGlobMatch/fo?_fo2401=== RUN TestGlobMatch/fo?_fooo2402=== PAUSE TestGlobMatch/fo?_fooo2403=== RUN TestGlobMatch/?oo_foo2404=== PAUSE TestGlobMatch/?oo_foo2405=== RUN TestGlobMatch/?oo_boo2406=== PAUSE TestGlobMatch/?oo_boo2407=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2408=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2409=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2410=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2411=== CONT TestGlobMatch/foo_foo2412=== CONT TestScopes_ConfigValidation2413--- PASS: TestScopes_ConfigValidation (0.00s)2414=== CONT TestScopes_LegacyProviderDefaultsToWrite2415=== CONT TestGlobMatch/*/*_foo/bar2416=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2417=== CONT TestGlobMatch/?oo_foo2418=== CONT TestGlobMatch/fo?_fooo2419=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02420=== CONT TestGlobMatch/fo?_foo2421=== CONT TestGlobMatch/*bar_bar2422=== CONT TestGlobMatch/refs/*/main_refs/heads/main2423=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2424=== CONT TestGlobMatch/foo*_foo2425=== CONT TestGlobMatch/foo*_bar2426=== CONT TestGlobMatch/foo*_foobar2427=== CONT TestGlobMatch/*_2428=== CONT TestGlobMatch/*_anything2429=== CONT TestGlobMatch/foo_bar2430=== CONT TestPins_ReservedForMatchingRule2431=== CONT TestGlobMatch/*/*_foo2432=== CONT TestPins_TopLevelShorthand2433=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2434=== CONT TestGlobMatch/foo*bar_foobarbaz2435=== CONT TestGlobMatch/foo*bar_foo123bar2436=== CONT TestGlobMatch/foo*bar_foobar2437=== CONT TestGlobMatch/*bar_foo2438=== CONT TestGlobMatch/*bar_foobar2439=== CONT TestGlobMatch/fo?_fo2440=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2441=== CONT TestGlobMatch/?oo_boo2442--- PASS: TestGlobMatch (0.00s)2443 --- PASS: TestGlobMatch/foo_foo (0.00s)2444 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2445 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2446 --- PASS: TestGlobMatch/?oo_foo (0.00s)2447 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2448 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2449 --- PASS: TestGlobMatch/*bar_bar (0.00s)2450 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2451 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2452 --- PASS: TestGlobMatch/foo*_foo (0.00s)2453 --- PASS: TestGlobMatch/foo*_bar (0.00s)2454 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2455 --- PASS: TestGlobMatch/*_ (0.00s)2456 --- PASS: TestGlobMatch/*_anything (0.00s)2457 --- PASS: TestGlobMatch/foo_bar (0.00s)2458 --- PASS: TestGlobMatch/fo?_foo (0.00s)2459 --- PASS: TestGlobMatch/*/*_foo (0.00s)2460 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2461 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2462 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2463 --- PASS: TestGlobMatch/*bar_foo (0.00s)2464 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2465 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2466 --- PASS: TestGlobMatch/fo?_fo (0.00s)2467 --- PASS: TestGlobMatch/?oo_boo (0.00s)24682026/11/01 17:51:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55824/oidc24692026/11/01 17:51:39 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5582624702026/11/01 17:51:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55828/oidc2471--- PASS: TestValidateToken_KubernetesServiceAccount (0.07s)2472--- PASS: TestValidateToken_ValidToken (0.06s)2473--- PASS: TestValidateToken_WrongAudience (0.07s)24742026/11/01 17:51:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55831/oidc2475--- PASS: TestPins_TopLevelShorthand (0.06s)24762026/11/01 17:51:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55836/oidc24772026/11/01 17:51:39 http: TLS handshake error from 127.0.0.1:55835: read tcp 127.0.0.1:55834->127.0.0.1:55835: use of closed network connection2478--- PASS: TestNewValidator_KubernetesRequiresCA (0.10s)2479--- PASS: TestScopes_Rules (0.11s)24802026/11/01 17:51:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55838/oidc24812026/11/01 17:51:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55840/oidc2482--- PASS: TestValidateToken_Expired (0.10s)2483--- PASS: TestValidateToken_BoundClaimsMismatch (0.11s)24842026/11/01 17:51:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55842/oidc24852026/11/01 17:51:39 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232486--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.09s)2487--- PASS: TestPins_ReservedForMatchingRule (0.10s)24882026/11/01 17:51:39 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:55833/oidc2489--- PASS: TestValidateToken_NoMatchingProvider (0.14s)24902026/11/01 17:51:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55849/oidc2491--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.14s)24922026/11/01 17:51:39 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:55851/oidc2493--- PASS: TestValidateToken_BoundSubjectMismatch (0.17s)24942026/11/01 17:51:39 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:55848/oidc24952026/11/01 17:51:39 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:55853/oidc2496--- PASS: TestValidateToken_MultipleProviders (0.20s)2497PASS2498Running hook tests...2499=== RUN TestSendPathsEmpty2500=== PAUSE TestSendPathsEmpty2501=== RUN TestQueueEnqueueAndFetch2502=== PAUSE TestQueueEnqueueAndFetch2503=== RUN TestQueueDeduplication2504=== PAUSE TestQueueDeduplication2505=== RUN TestQueueRemove2506=== PAUSE TestQueueRemove2507=== RUN TestQueueFetchBatchLimit2508=== PAUSE TestQueueFetchBatchLimit2509=== RUN TestQueueRetryMovesToBack2510=== PAUSE TestQueueRetryMovesToBack2511=== RUN TestQueueFetchRemoveLifecycle2512=== PAUSE TestQueueFetchRemoveLifecycle2513=== RUN TestQueueConcurrentWriters2514=== PAUSE TestQueueConcurrentWriters2515=== RUN TestQueueRemoveLargeClosure2516=== PAUSE TestQueueRemoveLargeClosure2517=== RUN TestServerClientIntegration2518--- PASS: TestServerClientIntegration (0.00s)2519=== RUN TestServerQueueError25202026/11/01 17:51:39 ERROR Failed to queue paths error="permission denied" count=12521--- PASS: TestServerQueueError (0.00s)2522=== RUN TestGetListenerSocketActivation2523 server_test.go:145: systemd socket activation does not exist on darwin2524--- SKIP: TestGetListenerSocketActivation (0.00s)2525=== RUN TestServerStalledClientDoesNotBlockShutdown2526=== PAUSE TestServerStalledClientDoesNotBlockShutdown2527=== RUN TestServerBacksOffOnAcceptErrors2528=== PAUSE TestServerBacksOffOnAcceptErrors2529=== RUN TestDrainIsolatesPoisonPath2530=== PAUSE TestDrainIsolatesPoisonPath2531=== RUN TestRunNotBlockedByPoisonHead2532=== PAUSE TestRunNotBlockedByPoisonHead2533=== RUN TestDrainGivesUpWhenServerDown2534=== PAUSE TestDrainGivesUpWhenServerDown2535=== RUN TestFailedPathPrunedByLaterClosure2536=== PAUSE TestFailedPathPrunedByLaterClosure2537=== RUN TestWorkerUploadsAndRemoves2538=== PAUSE TestWorkerUploadsAndRemoves2539=== RUN TestWorkerSkipsGCdPaths2540=== PAUSE TestWorkerSkipsGCdPaths2541=== RUN TestWorkerPrunesClosureDeps2542=== PAUSE TestWorkerPrunesClosureDeps2543=== RUN TestDrainTimeout2544=== PAUSE TestDrainTimeout2545=== RUN TestWorkerRemoveFailureIsNotProgress2546=== PAUSE TestWorkerRemoveFailureIsNotProgress2547=== RUN TestWorkerKeepsPathItCannotStat2548=== PAUSE TestWorkerKeepsPathItCannotStat2549=== CONT TestSendPathsEmpty2550=== CONT TestDrainIsolatesPoisonPath2551--- PASS: TestSendPathsEmpty (0.00s)2552=== CONT TestServerBacksOffOnAcceptErrors25532026/11/01 17:51:39 ERROR Accept failed error="too many open files"2554=== CONT TestServerStalledClientDoesNotBlockShutdown2555=== CONT TestQueueRemoveLargeClosure2556=== CONT TestQueueConcurrentWriters2557=== CONT TestQueueFetchRemoveLifecycle2558=== CONT TestQueueRetryMovesToBack2559=== CONT TestQueueFetchBatchLimit2560=== CONT TestQueueRemove2561=== CONT TestQueueDeduplication2562=== CONT TestWorkerSkipsGCdPaths2563=== CONT TestWorkerKeepsPathItCannotStat2564=== CONT TestQueueEnqueueAndFetch2565=== CONT TestWorkerRemoveFailureIsNotProgress2566=== CONT TestDrainTimeout2567=== CONT TestFailedPathPrunedByLaterClosure2568=== CONT TestWorkerPrunesClosureDeps2569=== CONT TestWorkerUploadsAndRemoves2570=== CONT TestDrainGivesUpWhenServerDown2571=== CONT TestRunNotBlockedByPoisonHead25722026/11/01 17:51:39 ERROR Accept failed error="too many open files"25732026/11/01 17:51:39 INFO Uploading batch count=125742026/11/01 17:51:39 ERROR Upload failed error="upload failed" count=125752026/11/01 17:51:39 INFO Upload queue status pending=225762026/11/01 17:51:39 INFO Uploading batch count=125772026/11/01 17:51:39 INFO Upload queue status pending=325782026/11/01 17:51:39 INFO Uploading batch count=125792026/11/01 17:51:39 ERROR Upload failed error="upload failed" count=12580--- PASS: TestQueueEnqueueAndFetch (0.01s)25812026/11/01 17:51:39 WARN Cannot stat store path, will retry later path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestWorkerKeepsPathItCannotStat1477506012/002/locked/aaa error="stat /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestWorkerKeepsPathItCannotStat1477506012/002/locked/aaa: permission denied"25822026/11/01 17:51:39 INFO Uploading batch count=125832026/11/01 17:51:39 WARN Cannot stat store path, will retry later path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestWorkerKeepsPathItCannotStat1477506012/002/locked/aaa error="stat /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestWorkerKeepsPathItCannotStat1477506012/002/locked/aaa: permission denied"25842026/11/01 17:51:39 WARN Cannot stat store path, will retry later path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestWorkerKeepsPathItCannotStat1477506012/002/locked/aaa error="stat /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestWorkerKeepsPathItCannotStat1477506012/002/locked/aaa: permission denied"25852026/11/01 17:51:39 INFO Upload queue status pending=225862026/11/01 17:51:39 INFO Uploading batch count=225872026/11/01 17:51:39 INFO Upload queue status pending=225882026/11/01 17:51:39 INFO Uploading batch count=425892026/11/01 17:51:39 ERROR Upload failed error="upload failed" count=425902026/11/01 17:51:39 ERROR Drain finished with paths left in queue remaining=125912026/11/01 17:51:39 INFO Uploading batch count=125922026/11/01 17:51:39 INFO Uploading batch count=225932026/11/01 17:51:39 ERROR Upload failed error="upload failed" count=225942026/11/01 17:51:39 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestDrainGivesUpWhenServerDown2491496585/002/a25952026/11/01 17:51:39 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestDrainGivesUpWhenServerDown2491496585/002/b25962026/11/01 17:51:39 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestWorkerSkipsGCdPaths3681686680/002/nonexistent2597--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25982026/11/01 17:51:39 INFO Uploading batch count=225992026/11/01 17:51:39 ERROR Upload failed error="upload failed" count=226002026/11/01 17:51:39 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestDrainGivesUpWhenServerDown2491496585/002/c2601--- PASS: TestQueueDeduplication (0.01s)26022026/11/01 17:51:39 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestDrainGivesUpWhenServerDown2491496585/002/d26032026/11/01 17:51:39 INFO Uploading batch count=226042026/11/01 17:51:39 INFO Uploading batch count=226052026/11/01 17:51:39 ERROR Upload failed error="upload failed" count=226062026/11/01 17:51:39 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestDrainGivesUpWhenServerDown2491496585/002/e26072026/11/01 17:51:39 INFO Uploading batch count=12608--- PASS: TestQueueRetryMovesToBack (0.01s)26092026/11/01 17:51:39 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestDrainIsolatesPoisonPath3177479632/002/bbb2610--- PASS: TestQueueRemove (0.01s)26112026/11/01 17:51:39 ERROR Accept failed error="too many open files"2612--- PASS: TestQueueFetchBatchLimit (0.02s)26132026/11/01 17:51:39 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestDrainGivesUpWhenServerDown2491496585/002/f26142026/11/01 17:51:39 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestWorkerRemoveFailureIsNotProgress37444460/002/nonexistent26152026/11/01 17:51:39 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126162026/11/01 17:51:39 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestWorkerRemoveFailureIsNotProgress37444460/002/nonexistent26172026/11/01 17:51:39 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126182026/11/01 17:51:39 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestWorkerRemoveFailureIsNotProgress37444460/002/nonexistent26192026/11/01 17:51:39 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=12620--- PASS: TestWorkerKeepsPathItCannotStat (0.01s)2621--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)26222026/11/01 17:51:39 ERROR Drain finished with paths left in queue remaining=1026232026/11/01 17:51:39 ERROR Drain finished with paths left in queue remaining=126242026/11/01 17:51:39 INFO Uploading batch count=126252026/11/01 17:51:39 ERROR Upload failed error="upload failed" count=12626--- PASS: TestWorkerRemoveFailureIsNotProgress (0.01s)26272026/11/01 17:51:39 INFO Uploading batch count=126282026/11/01 17:51:39 ERROR Upload failed error="upload failed" count=126292026/11/01 17:51:39 INFO Uploading batch count=126302026/11/01 17:51:39 ERROR Upload failed error="upload failed" count=126312026/11/01 17:51:39 ERROR Drain finished with paths left in queue remaining=12632--- PASS: TestDrainGivesUpWhenServerDown (0.01s)2633--- PASS: TestDrainIsolatesPoisonPath (0.02s)2634--- PASS: TestWorkerPrunesClosureDeps (0.03s)2635--- PASS: TestWorkerSkipsGCdPaths (0.03s)2636--- PASS: TestWorkerUploadsAndRemoves (0.03s)26372026/11/01 17:51:39 ERROR Accept failed error="too many open files"2638--- PASS: TestQueueRemoveLargeClosure (0.04s)2639--- PASS: TestQueueConcurrentWriters (0.04s)26402026/11/01 17:51:40 ERROR Accept failed error="too many open files"26412026/11/01 17:51:40 ERROR Accept failed error="too many open files"26422026/11/01 17:51:40 ERROR Failed to decode request error="read unix /private/var/tb/2/scratch/fe9bd16a51fa0841/build/hook2400940846/test.sock->: i/o timeout"26432026/11/01 17:51:40 ERROR Failed to write response error="write unix /private/var/tb/2/scratch/fe9bd16a51fa0841/build/hook2400940846/test.sock->: i/o timeout"2644--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26452026/11/01 17:51:40 ERROR Upload failed error="context deadline exceeded" count=226462026/11/01 17:51:40 ERROR Drain finished with paths left in queue remaining=42647--- PASS: TestDrainTimeout (0.22s)26482026/11/01 17:51:40 ERROR Accept failed error="too many open files"26492026/11/01 17:51:40 ERROR Accept failed error="too many open files"2650--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26512026/11/01 17:51:40 INFO Uploading batch count=126522026/11/01 17:51:40 INFO Uploading batch count=126532026/11/01 17:51:40 INFO Uploading batch count=126542026/11/01 17:51:40 ERROR Upload failed error="upload failed" count=126552026/11/01 17:51:40 INFO Uploading batch count=126562026/11/01 17:51:40 ERROR Upload failed error="upload failed" count=126572026/11/01 17:51:40 INFO Uploading batch count=126582026/11/01 17:51:40 ERROR Upload failed error="upload failed" count=126592026/11/01 17:51:40 INFO Uploading batch count=126602026/11/01 17:51:40 ERROR Upload failed error="upload failed" count=126612026/11/01 17:51:40 ERROR Drain finished with paths left in queue remaining=12662--- PASS: TestRunNotBlockedByPoisonHead (1.03s)2663PASS2664Running signing tests...2665=== RUN TestExternalSigner2666=== PAUSE TestExternalSigner2667=== RUN TestExternalSignerWrongPublicKey2668=== PAUSE TestExternalSignerWrongPublicKey2669=== RUN TestExternalSignerErrors2670=== PAUSE TestExternalSignerErrors2671=== RUN TestExternalSignerRestartsAfterCrash2672=== PAUSE TestExternalSignerRestartsAfterCrash2673=== RUN TestExternalSignerProgramErrorKeepsProcess2674=== PAUSE TestExternalSignerProgramErrorKeepsProcess2675=== RUN TestExternalSignerClose2676=== PAUSE TestExternalSignerClose2677=== RUN TestExternalSignerRejectsInvalidPublicKey2678=== PAUSE TestExternalSignerRejectsInvalidPublicKey2679=== RUN TestExternalSignerCancellation2680=== PAUSE TestExternalSignerCancellation2681=== RUN TestGenerateFingerprint2682=== PAUSE TestGenerateFingerprint2683=== RUN TestParseSigningKey2684=== PAUSE TestParseSigningKey2685=== RUN TestSign2686=== PAUSE TestSign2687=== RUN TestSignBatch2688=== PAUSE TestSignBatch2689=== RUN TestNilKeyPublicKey2690=== PAUSE TestNilKeyPublicKey2691=== RUN TestSignErrors2692=== PAUSE TestSignErrors2693=== CONT TestExternalSigner2694=== CONT TestSignBatch2695=== CONT TestExternalSignerCancellation2696=== CONT TestSignErrors2697=== CONT TestExternalSignerProgramErrorKeepsProcess2698=== CONT TestParseSigningKey2699=== RUN TestParseSigningKey/valid_32-byte_key2700=== PAUSE TestParseSigningKey/valid_32-byte_key2701=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2702=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2703=== RUN TestParseSigningKey/no_colon2704=== PAUSE TestParseSigningKey/no_colon2705=== RUN TestParseSigningKey/empty_name2706=== CONT TestSign2707=== PAUSE TestParseSigningKey/empty_name2708=== CONT TestGenerateFingerprint2709=== RUN TestGenerateFingerprint/basic_with_references2710=== CONT TestExternalSignerErrors2711=== PAUSE TestGenerateFingerprint/basic_with_references2712=== RUN TestGenerateFingerprint/no_references2713=== PAUSE TestGenerateFingerprint/no_references2714=== RUN TestExternalSignerErrors/wrong_shape2715=== CONT TestExternalSignerRejectsInvalidPublicKey2716=== PAUSE TestExternalSignerErrors/wrong_shape2717=== CONT TestExternalSignerWrongPublicKey2718=== RUN TestExternalSignerErrors/missing_signatures2719=== PAUSE TestExternalSignerErrors/missing_signatures2720=== RUN TestExternalSignerErrors/wrong_signature_length2721=== CONT TestNilKeyPublicKey2722--- PASS: TestNilKeyPublicKey (0.00s)2723=== RUN TestParseSigningKey/invalid_base642724=== PAUSE TestParseSigningKey/invalid_base642725=== RUN TestParseSigningKey/wrong_length2726=== CONT TestExternalSignerRestartsAfterCrash2727=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2728=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2729=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2730=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2731=== RUN TestGenerateFingerprint/invalid_nar_hash_length2732=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2733=== RUN TestGenerateFingerprint/invalid_store_path_prefix2734=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2735=== RUN TestGenerateFingerprint/invalid_reference_prefix2736=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2737=== CONT TestGenerateFingerprint/basic_with_references2738=== RUN TestExternalSignerRejectsInvalidPublicKey/#002739=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002740=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2741=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2742=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2743=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2744=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2745=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2746=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2747=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2748=== CONT TestExternalSignerRejectsInvalidPublicKey/#002749=== PAUSE TestExternalSignerErrors/wrong_signature_length2750=== RUN TestExternalSignerErrors/wrong_id2751=== PAUSE TestExternalSignerErrors/wrong_id2752=== RUN TestExternalSignerErrors/too_few_signatures2753=== PAUSE TestExternalSignerErrors/too_few_signatures2754=== RUN TestExternalSignerErrors/unrequested_key2755=== PAUSE TestExternalSignerErrors/unrequested_key2756=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2757=== CONT TestGenerateFingerprint/no_references2758=== PAUSE TestParseSigningKey/wrong_length2759=== CONT TestParseSigningKey/valid_32-byte_key2760=== CONT TestGenerateFingerprint/invalid_reference_prefix2761=== CONT TestGenerateFingerprint/invalid_store_path_prefix2762=== CONT TestGenerateFingerprint/invalid_nar_hash_length2763=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2764--- PASS: TestGenerateFingerprint (0.00s)2765 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2766 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2767 --- PASS: TestGenerateFingerprint/no_references (0.00s)2768 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2769 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2770 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2771 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2772=== CONT TestParseSigningKey/wrong_length2773=== CONT TestParseSigningKey/invalid_base642774=== CONT TestParseSigningKey/empty_name2775=== CONT TestParseSigningKey/no_colon2776=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2777=== RUN TestExternalSignerErrors/program_error2778=== PAUSE TestExternalSignerErrors/program_error2779=== RUN TestExternalSignerErrors/invalid_JSON2780=== PAUSE TestExternalSignerErrors/invalid_JSON2781=== RUN TestExternalSignerErrors/exit_at_startup2782=== PAUSE TestExternalSignerErrors/exit_at_startup2783=== RUN TestExternalSignerErrors/exit_on_request2784=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2785=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2786=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2787=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2788--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2789 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2790 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2791 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2792 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2793 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2794=== CONT TestExternalSignerClose2795=== PAUSE TestExternalSignerErrors/exit_on_request2796=== RUN TestExternalSignerErrors/null2797=== PAUSE TestExternalSignerErrors/null2798=== RUN TestExternalSignerErrors/null_signatures2799=== PAUSE TestExternalSignerErrors/null_signatures2800=== RUN TestExternalSignerErrors/wrong_signatures_shape2801=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2802=== RUN TestExternalSignerErrors/missing_signature_name2803=== PAUSE TestExternalSignerErrors/missing_signature_name2804=== RUN TestExternalSignerErrors/wrong_signature_name2805=== PAUSE TestExternalSignerErrors/wrong_signature_name2806=== RUN TestExternalSignerErrors/invalid_signature_base642807=== PAUSE TestExternalSignerErrors/invalid_signature_base642808=== CONT TestExternalSignerErrors/wrong_shape2809=== CONT TestExternalSignerErrors/exit_at_startup2810=== CONT TestExternalSignerErrors/wrong_id2811=== CONT TestExternalSignerErrors/wrong_signature_name2812=== CONT TestExternalSignerErrors/null_signatures2813=== CONT TestExternalSignerErrors/too_few_signatures2814--- PASS: TestSignBatch (0.00s)2815--- PASS: TestSign (0.00s)2816=== CONT TestExternalSignerErrors/exit_on_request2817=== CONT TestExternalSignerErrors/invalid_JSON2818=== CONT TestExternalSignerErrors/wrong_signature_length2819=== CONT TestExternalSignerErrors/missing_signature_name2820--- PASS: TestParseSigningKey (0.00s)2821 --- PASS: TestParseSigningKey/wrong_length (0.00s)2822 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2823 --- PASS: TestParseSigningKey/empty_name (0.00s)2824 --- PASS: TestParseSigningKey/no_colon (0.00s)2825 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2826 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2827=== CONT TestExternalSignerErrors/program_error2828=== CONT TestExternalSignerErrors/missing_signatures2829=== CONT TestExternalSignerErrors/unrequested_key2830=== CONT TestExternalSignerErrors/wrong_signatures_shape2831=== CONT TestExternalSignerErrors/invalid_signature_base642832=== CONT TestExternalSignerErrors/null2833=== RUN TestSignErrors/nil_key2834=== PAUSE TestSignErrors/nil_key2835=== RUN TestSignErrors/nil_narinfo2836=== PAUSE TestSignErrors/nil_narinfo2837=== RUN TestSignErrors/invalid_narinfo2838=== PAUSE TestSignErrors/invalid_narinfo2839=== RUN TestSignErrors/canceled2840=== PAUSE TestSignErrors/canceled2841=== CONT TestSignErrors/nil_key2842=== CONT TestSignErrors/nil_narinfo2843=== CONT TestSignErrors/canceled2844=== CONT TestSignErrors/invalid_narinfo2845--- PASS: TestSignErrors (0.00s)2846 --- PASS: TestSignErrors/nil_key (0.00s)2847 --- PASS: TestSignErrors/nil_narinfo (0.00s)2848 --- PASS: TestSignErrors/canceled (0.00s)2849 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2850--- PASS: TestExternalSignerRestartsAfterCrash (0.25s)2851/private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestExternalSignerRestartsAfterCrash3027641590/001/sign program: line 7: /private/var/tb/2/scratch/fe9bd16a51fa0841/build/TestExternalSignerRestartsAfterCrash3027641590/001/sign program.starts: No such file or directory2852--- PASS: TestExternalSignerClose (0.41s)2853--- PASS: TestExternalSignerCancellation (0.63s)2854--- PASS: TestExternalSignerWrongPublicKey (1.76s)2855--- PASS: TestExternalSignerProgramErrorKeepsProcess (2.72s)2856--- PASS: TestExternalSigner (3.51s)2857--- PASS: TestExternalSignerErrors (0.00s)2858 --- PASS: TestExternalSignerErrors/missing_signature_name (0.81s)2859 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (1.00s)2860 --- PASS: TestExternalSignerErrors/wrong_id (1.19s)2861 --- PASS: TestExternalSignerErrors/too_few_signatures (1.38s)2862 --- PASS: TestExternalSignerErrors/wrong_signature_name (1.57s)2863 --- PASS: TestExternalSignerErrors/program_error (1.95s)2864 --- PASS: TestExternalSignerErrors/wrong_signature_length (2.15s)2865 --- PASS: TestExternalSignerErrors/missing_signatures (2.33s)2866 --- PASS: TestExternalSignerErrors/null (2.52s)2867 --- PASS: TestExternalSignerErrors/exit_on_request (2.91s)2868 --- PASS: TestExternalSignerErrors/exit_at_startup (3.10s)2869 --- PASS: TestExternalSignerErrors/unrequested_key (3.29s)2870 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (3.68s)2871 --- PASS: TestExternalSignerErrors/invalid_JSON (3.87s)2872 --- PASS: TestExternalSignerErrors/wrong_shape (4.06s)2873 --- PASS: TestExternalSignerErrors/null_signatures (4.26s)2874PASS2875Running OpenBao signer tests...2876=== RUN TestSign2877=== PAUSE TestSign2878=== RUN TestSignErrors2879=== PAUSE TestSignErrors2880=== RUN TestServe2881=== PAUSE TestServe2882=== RUN TestServeRejectsGarbage2883=== PAUSE TestServeRejectsGarbage2884=== CONT TestSign2885=== CONT TestServeRejectsGarbage2886=== CONT TestSignErrors2887=== CONT TestServe2888--- PASS: TestServeRejectsGarbage (0.00s)2889=== RUN TestSignErrors/invalid_json2890=== PAUSE TestSignErrors/invalid_json2891=== RUN TestSignErrors/no_prefix2892=== PAUSE TestSignErrors/no_prefix2893=== RUN TestSignErrors/invalid_base642894=== PAUSE TestSignErrors/invalid_base642895=== RUN TestSignErrors/http_error2896=== PAUSE TestSignErrors/http_error2897=== CONT TestSignErrors/invalid_json2898=== CONT TestSignErrors/invalid_base642899=== CONT TestSignErrors/no_prefix2900--- PASS: TestServe (0.00s)2901=== CONT TestSignErrors/http_error2902--- PASS: TestSign (0.00s)2903--- PASS: TestSignErrors (0.00s)2904 --- PASS: TestSignErrors/no_prefix (0.00s)2905 --- PASS: TestSignErrors/invalid_base64 (0.00s)2906 --- PASS: TestSignErrors/invalid_json (0.00s)2907 --- PASS: TestSignErrors/http_error (0.00s)2908PASS