niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #459
· 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.13s)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 TestStaticToken117=== CONT TestScriptTokenNoExpiryRerunsEveryCall118=== CONT TestFileTokenEmpty119=== CONT TestSupersededNARStillUploadsListing120=== RUN TestSupersededNARStillUploadsListing/small_NAR121--- PASS: TestStaticToken (0.00s)122=== PAUSE TestSupersededNARStillUploadsListing/small_NAR123=== CONT TestSetClientTLS124=== CONT TestScriptTokenScriptFails125=== CONT TestScriptTokenBadJSON126=== CONT TestScriptTokenEmptyToken127=== CONT TestScriptTokenCachesUntilRefresh128=== CONT TestFileTokenMissing129=== CONT TestPathInfoCACompatibility130=== CONT TestSetClientTLSErrors131=== CONT TestSetClientTLSDoesNotMutateDefaultTransport132=== CONT TestStreamPushStopsWhenCanceled133=== CONT TestClientSignaturesByStorePath134--- PASS: TestFileTokenEmpty (0.00s)135=== CONT TestStreamPushReportsSignatures136=== CONT TestStreamPushRequestLine137=== CONT TestStreamPushGivesUpOnDeadServer138=== CONT TestStreamPushIsolatesFailures139=== CONT TestStreamPushBatchesUnderLoad140=== CONT TestStreamPushReportsEveryPath141=== CONT TestFileTokenReadsAndCaches1422026/11/03 08:17:16 ERROR Upload failed error="connection refused" count=201432026/11/03 08:17:16 ERROR Server seems unavailable, giving up on batch untried=171442026/11/03 08:17:16 ERROR Upload failed error=boom count=1145=== CONT TestDoWithRetry_BodyReplayedViaGetBody1462026/11/03 08:17:16 ERROR Upload failed error=boom count=11472026/11/03 08:17:16 ERROR Upload failed error="bad path" count=3148=== CONT TestScriptTokenEmptyCommand149=== CONT TestRateLimiterFeedback150=== RUN TestRateLimiterFeedback/429_enables_limiter151=== CONT TestResolveStorePath152=== PAUSE TestRateLimiterFeedback/429_enables_limiter153=== RUN TestRateLimiterFeedback/503_enables_limiter154=== PAUSE TestRateLimiterFeedback/503_enables_limiter155=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter156=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter157=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter158=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter159=== RUN TestSupersededNARStillUploadsListing/dump_cut_short160=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short1612026/11/03 08:17:16 WARN Rate limiter enabled after throttle name=server-test rate=5162=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails163=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails1642026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:50795165=== RUN TestPathInfoCACompatibility/null_ca_field166=== PAUSE TestPathInfoCACompatibility/null_ca_field167--- PASS: TestStreamPushStopsWhenCanceled (0.00s)168=== CONT TestStreamPushReportsSkippedPaths169=== CONT TestRetryTimeoutOutlastsMaxRetries170=== CONT TestPartSizeForNAR171=== RUN TestPartSizeForNAR/zero_stays_at_minimum172=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum173=== RUN TestPartSizeForNAR/small_stays_at_minimum174=== PAUSE TestPartSizeForNAR/small_stays_at_minimum175=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum176=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum177=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts178=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts179=== RUN TestPartSizeForNAR/1_TiB180=== PAUSE TestPartSizeForNAR/1_TiB181=== RUN TestPartSizeForNAR/5_TiB_S3_max_object182=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object183=== RUN TestPartSizeForNAR/capped_at_5_GiB184=== PAUSE TestPartSizeForNAR/capped_at_5_GiB185=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry186=== CONT TestShellSplitErrors187=== CONT TestUploadMultipart_SupersededByPeer188=== RUN TestUploadMultipart_SupersededByPeer/exists189=== PAUSE TestUploadMultipart_SupersededByPeer/exists190=== RUN TestUploadMultipart_SupersededByPeer/missing191=== PAUSE TestUploadMultipart_SupersededByPeer/missing192=== CONT TestUploadMultipart_PartsInParallel193=== CONT TestShellSplit194=== CONT TestDoWithRetry_FinalResponseBodyReadable195=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false196=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer197=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess198=== CONT TestRegisterUploadedObjectReusesConnections199=== CONT TestCaseHackSuffix200=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun201=== RUN TestPathInfoCACompatibility/old_string_format_-_text202--- PASS: TestClientSignaturesByStorePath (0.00s)203--- PASS: TestFileTokenMissing (0.00s)204--- PASS: TestStreamPushReportsSignatures (0.00s)205--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)206--- PASS: TestStreamPushReportsEveryPath (0.00s)207--- PASS: TestStreamPushIsolatesFailures (0.00s)208--- PASS: TestScriptTokenEmptyCommand (0.00s)209--- PASS: TestResolveStorePath (0.00s)210--- PASS: TestScriptTokenScriptFails (0.01s)211--- PASS: TestStreamPushReportsSkippedPaths (0.00s)212--- PASS: TestShellSplitErrors (0.00s)2132026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:50798214=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica215=== RUN TestSetClientTLSErrors/missing_cert_file216=== PAUSE TestSetClientTLSErrors/missing_cert_file217=== RUN TestSetClientTLSErrors/missing_key_file218=== PAUSE TestSetClientTLSErrors/missing_key_file219=== RUN TestSetClientTLSErrors/missing_ca_file220=== PAUSE TestSetClientTLSErrors/missing_ca_file221=== RUN TestSetClientTLSErrors/invalid_ca_file2222026/11/03 08:17:16 WARN Rate limiter backed off name=server-test rate=52232026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:50795224--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.01s)225=== CONT TestUploadMultipart_FailedPartBufferNotReused226--- PASS: TestFileTokenReadsAndCaches (0.01s)227=== CONT TestConvertHashToNix32228=== RUN TestConvertHashToNix32/SRI_format_to_Nix32229=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32230=== RUN TestConvertHashToNix32/already_Nix32_format231=== PAUSE TestConvertHashToNix32/already_Nix32_format232=== RUN TestConvertHashToNix32/invalid_format233=== PAUSE TestConvertHashToNix32/invalid_format234=== CONT TestDumpPathWriterError235=== RUN TestSetClientTLS/rejects_connection_without_client_cert236=== PAUSE TestSetClientTLSErrors/invalid_ca_file237=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text238=== CONT TestEncodeNixBase32WithRealHash239=== CONT TestParsePathInfoJSON240=== RUN TestParsePathInfoJSON/Nix_format241=== PAUSE TestParsePathInfoJSON/Nix_format2422026/11/03 08:17:16 WARN Rate limiter enabled after throttle name=server-test rate=5243=== CONT TestParsePathInfoJSONMultiplePaths244=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths245=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths246=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths247=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths248=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false249=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true250=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive251=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive252=== RUN TestPathInfoCACompatibility/new_structured_format_-_text253=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text254=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method255=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method256=== RUN TestParsePathInfoJSON/Lix_format257=== PAUSE TestParsePathInfoJSON/Lix_format258--- PASS: TestShellSplit (0.00s)259--- PASS: TestEncodeNixBase32WithRealHash (0.00s)260=== CONT TestEncodeNixBase32261=== RUN TestEncodeNixBase32/test_string_hash262=== PAUSE TestEncodeNixBase32/test_string_hash263--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.02s)264=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert265=== CONT TestGetStorePathHash266=== RUN TestGetStorePathHash/valid_store_path267=== PAUSE TestGetStorePathHash/valid_store_path268=== RUN TestGetStorePathHash/basename_without_hyphen_should_error269=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error270=== CONT TestPathInfoHashCompatibility271=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)272=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)273=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon274=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon275=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI276=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI277=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512278=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512279=== RUN TestParsePathInfoJSON/empty_input280=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true281=== CONT TestDumpPathSingleFile2822026/11/03 08:17:16 INFO Garbage collection started2832026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:50798284--- PASS: TestScriptTokenBadJSON (0.02s)285--- PASS: TestScriptTokenEmptyToken (0.02s)286=== CONT TestFilterOversizedClosures287=== RUN TestFilterOversizedClosures/no_limit_keeps_everything288=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything289=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped290=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped2912026/11/03 08:17:16 WARN Rate limiter enabled after throttle name=server-test rate=5292=== RUN TestFilterOversizedClosures/all_closures_skipped2932026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:50808294=== PAUSE TestFilterOversizedClosures/all_closures_skipped295=== CONT TestRateLimiterFeedback/429_enables_limiter296=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter297=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error298=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error299=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error300=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error301=== PAUSE TestParsePathInfoJSON/empty_input302=== RUN TestParsePathInfoJSON/whitespace_only303=== PAUSE TestParsePathInfoJSON/whitespace_only304=== RUN TestParsePathInfoJSON/invalid_JSON305=== PAUSE TestParsePathInfoJSON/invalid_JSON306=== CONT TestRateLimiterFeedback/503_enables_limiter307=== RUN TestEncodeNixBase32/empty_input308=== PAUSE TestEncodeNixBase32/empty_input309=== CONT TestSupersededNARStillUploadsListing/small_NAR310=== CONT TestDumpPathMatchesNix311=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails312=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA313=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA314=== RUN TestSetClientTLS/preserves_debug_logging_transport315=== PAUSE TestSetClientTLS/preserves_debug_logging_transport316=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter317=== CONT TestSupersededNARStillUploadsListing/dump_cut_short318--- PASS: TestDoServerRequestAttachesToken (0.03s)3192026/11/03 08:17:16 WARN Rate limiter backed off name=server-test rate=53202026/11/03 08:17:16 WARN Rate limiter enabled after throttle name=server-test rate=53212026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:508213222026/11/03 08:17:16 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=03232026/11/03 08:17:16 WARN Rate limiter enabled after throttle name=s3-test rate=53242026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:50810325--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)326=== CONT TestUploadMultipart_SupersededByPeer/exists327=== CONT TestPartSizeForNAR/zero_stays_at_minimum328=== CONT TestPartSizeForNAR/capped_at_5_GiB329=== CONT TestPartSizeForNAR/5_TiB_S3_max_object330=== CONT TestPartSizeForNAR/1_TiB331=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts332=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum333=== CONT TestPartSizeForNAR/small_stays_at_minimum334--- PASS: TestPartSizeForNAR (0.00s)335 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)336 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)337 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)338 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)339 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)340 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)341 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)342=== CONT TestUploadMultipart_SupersededByPeer/missing343--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s)344=== CONT TestConvertHashToNix32/SRI_format_to_Nix32345=== CONT TestConvertHashToNix32/invalid_format346=== CONT TestConvertHashToNix32/already_Nix32_format347--- PASS: TestConvertHashToNix32 (0.00s)348 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)349 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)350 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)351=== CONT TestSetClientTLSErrors/missing_cert_file3522026/11/03 08:17:16 INFO Garbage collection started3532026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:507983542026/11/03 08:17:16 WARN Rate limiter backed off name=server-test rate=5355=== CONT TestSetClientTLSErrors/invalid_ca_file356=== CONT TestSetClientTLSErrors/missing_ca_file357=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths358=== CONT TestSetClientTLSErrors/missing_key_file3592026/11/03 08:17:16 WARN Garbage collection finished on another replica. Its statistics are not available here3602026/11/03 08:17:16 WARN Rate limiter enabled after throttle name=server-test rate=53612026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:508613622026/11/03 08:17:16 WARN Rate limiter backed off name=server-test rate=53632026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:507983642026/11/03 08:17:16 INFO Uploading abc-hello (1.0GB)3652026/11/03 08:17:16 INFO Uploading abc-hello (1.0GB)366=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths367=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)368=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512369=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI370=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon371=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false372--- PASS: TestStreamPushRequestLine (0.03s)373--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.03s)374--- PASS: TestSetClientTLSErrors (0.03s)375 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)376 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)377 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)378 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)379--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.02s)380--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)381 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)382 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)383=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method384=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true385=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive386=== CONT TestFilterOversizedClosures/no_limit_keeps_everything387=== CONT TestPathInfoCACompatibility/null_ca_field388=== CONT TestFilterOversizedClosures/all_closures_skipped3892026/11/03 08:17:16 WARN Skipping closure: path exceeds server max NAR size top_level_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper oversized_path=/nix/store/cccccccccccccccccccccccccccccccc-wrapper nar_size=100 max_nar_size=50390=== CONT TestGetStorePathHash/valid_store_path391=== CONT TestPathInfoCACompatibility/old_string_format_-_text392=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped3932026/11/03 08:17:16 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=2000394--- PASS: TestPathInfoHashCompatibility (0.00s)395 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)396 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)397 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)398 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)399--- PASS: TestFilterOversizedClosures (0.00s)400 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)401 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)402 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)403=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error404=== CONT TestParsePathInfoJSON/invalid_JSON405=== CONT TestParsePathInfoJSON/whitespace_only406=== CONT TestParsePathInfoJSON/empty_input407=== CONT TestParsePathInfoJSON/Lix_format408=== CONT TestSetClientTLS/rejects_connection_without_client_cert409=== CONT TestSetClientTLS/preserves_debug_logging_transport410--- PASS: TestRateLimiterFeedback (0.00s)411 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)412 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.00s)413 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.01s)414 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.02s)415=== CONT TestParsePathInfoJSON/Nix_format416=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA417--- PASS: TestParsePathInfoJSON (0.01s)418 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)419 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)420 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)421 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)422 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)423--- PASS: TestStreamPushBatchesUnderLoad (0.02s)424 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)425 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)426=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error427=== CONT TestGetStorePathHash/basename_without_hyphen_should_error428--- PASS: TestGetStorePathHash (0.00s)429 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)430 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)431 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)432 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)433=== CONT TestEncodeNixBase32/empty_input434=== CONT TestEncodeNixBase32/test_string_hash435--- PASS: TestEncodeNixBase32 (0.00s)436 --- PASS: TestEncodeNixBase32/empty_input (0.00s)437 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)438=== CONT TestPathInfoCACompatibility/new_structured_format_-_text439--- PASS: TestPathInfoCACompatibility (0.02s)440 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)441 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)442 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)443 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)444 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)445--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)446 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.02s)447 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.02s)4482026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:507984492026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:507984502026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:50798451--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.05s)4522026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:507984532026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:507984542026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:507984552026/11/03 08:17:16 WARN Rate limiter enabled after throttle name=s3-test rate=54562026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:507984572026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:507984582026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:507984592026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:507984602026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:507984612026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:507984622026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:50798463--- PASS: TestRegisterUploadedObjectReusesConnections (0.05s)4642026/11/03 08:17:16 http: TLS handshake error from 127.0.0.1:50899: read tcp 127.0.0.1:50803->127.0.0.1:50899: use of closed network connection4652026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:50798466--- PASS: TestSetClientTLS (0.03s)467 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.01s)468 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.02s)469 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.03s)4702026/11/03 08:17:16 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:50798471--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.07s)472--- PASS: TestScriptTokenCachesUntilRefresh (0.08s)473--- PASS: TestDumpPathSingleFile (0.06s)474--- PASS: TestCaseHackSuffix (0.08s)4752026/11/03 08:17:16 INFO Uploading abc-hello (1.0GB)476--- PASS: TestDumpPathWriterError (0.09s)4772026/11/03 08:17:16 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:50853/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:50853/part/24782026/11/03 08:17:16 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:50853/part/3\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:50853/part/34792026/11/03 08:17:16 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:50853/part/4\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:50853/part/44802026/11/03 08:17:16 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"481--- PASS: TestDumpPathMatchesNix (0.13s)482--- PASS: TestSupersededNARStillUploadsListing (0.01s)483 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.03s)484 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.03s)485 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.59s)486--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.60s)487--- PASS: TestUploadMultipart_PartsInParallel (0.64s)4882026/11/03 08:17:17 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:50809/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:50809/api/uploads/complete4892026/11/03 08:17:17 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/03 08:17:17 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:50809/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:50809/api/uploads/complete4922026/11/03 08:17:17 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4932026/11/03 08:17:17 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:50809/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:50809/api/uploads/complete4942026/11/03 08:17:17 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"495--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.01s)496PASS497Running server tests...498The files belonging to this database system will be owned by user "_tribuchetbld4".499This user must also own the server process.500501The database cluster will be initialized with locale "C".502The default database encoding has accordingly been set to "SQL_ASCII".503The default text search configuration will be set to "english".504505Data page checksums are enabled.506507creating directory /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/postgres4070471039/data ... ok508creating subdirectories ... ok509selecting dynamic shared memory implementation ... posix510selecting default "max_connections" ... 100511selecting default "shared_buffers" ... 128MB512selecting default time zone ... UTC513creating configuration files ... ok514running bootstrap script ... ok515performing post-bootstrap initialization ... ok516syncing data to disk ... ok517518initdb: warning: enabling "trust" authentication for local connections519initdb: 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.520521Success. You can now start the database server using:522523 pg_ctl -D /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/postgres4070471039/data -l logfile start524525/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/postgres4070471039:5432 - no response5262026-11-03 08:17:18.093 UTC [28455] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5272026-11-03 08:17:18.093 UTC [28455] LOG: listening on Unix socket "/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/postgres4070471039/.s.PGSQL.5432"5282026-11-03 08:17:18.095 UTC [28462] LOG: database system was shut down at 2026-11-03 08:17:18 UTC5292026-11-03 08:17:18.096 UTC [28455] LOG: database system is ready to accept connections530/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/postgres4070471039:5432 - accepting connections531{"timestamp":"2026-11-03T08:17:20.363202Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"4c0c9f92-c7e8-4556-9330-a83d5e1e3b24","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":1,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(3)"}532=== RUN TestService_AuthMiddleware533=== PAUSE TestService_AuthMiddleware534=== RUN TestService_AuthMiddleware_MTLSProxyHeader535=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader536=== RUN TestService_AuthMiddleware_MTLSBoundSubjects537=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects538=== RUN TestService_ReadAuthMiddleware539=== PAUSE TestService_ReadAuthMiddleware540=== RUN TestService_AuthMiddleware_OIDC541=== PAUSE TestService_AuthMiddleware_OIDC542=== RUN TestService_RequireScope_OIDC543=== PAUSE TestService_RequireScope_OIDC544=== RUN TestService_ReadScope_PublicByDefault545=== PAUSE TestService_ReadScope_PublicByDefault546=== RUN TestCacheConfigHandler547=== PAUSE TestCacheConfigHandler548=== RUN TestCacheStatsHandler549=== PAUSE TestCacheStatsHandler550=== RUN TestClientCADerivations551=== PAUSE TestClientCADerivations552=== RUN TestClientErrorHandling553=== PAUSE TestClientErrorHandling554=== RUN TestClientIntegration555=== PAUSE TestClientIntegration556=== RUN TestClientMultipleUploads557=== PAUSE TestClientMultipleUploads558=== RUN TestClientWithDependencies559=== PAUSE TestClientWithDependencies560=== RUN TestClientSharedPathCommittedMidPush561=== PAUSE TestClientSharedPathCommittedMidPush562=== RUN TestPinProtectsFromGC563=== PAUSE TestPinProtectsFromGC564=== RUN TestClientPushesUseOnePush565=== PAUSE TestClientPushesUseOnePush566=== RUN TestClientFallsBackToClosures567=== PAUSE TestClientFallsBackToClosures568=== RUN TestDeleteClosuresRacingPins569=== PAUSE TestDeleteClosuresRacingPins570=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock571=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock572=== RUN TestResolveDBConnectionString573=== PAUSE TestResolveDBConnectionString574=== RUN TestConnectWaitsForAPeerMigration575=== PAUSE TestConnectWaitsForAPeerMigration576=== RUN TestLeadElectsOneAndHandsOver577=== PAUSE TestLeadElectsOneAndHandsOver578=== RUN TestLeadIncumbentWinsAfterRestart5792026/11/03 08:17:20 INFO lead: acquired remote=192.0.2.1:12345802026/11/03 08:17:21 INFO lead: released remote=192.0.2.1:12345812026/11/03 08:17:21 INFO lead: acquired remote=192.0.2.1:12345822026/11/03 08:17:22 INFO lead: released remote=192.0.2.1:1234583--- PASS: TestLeadIncumbentWinsAfterRestart (1.97s)584=== RUN TestLeadIncumbentAnnouncesAtOnce585=== PAUSE TestLeadIncumbentAnnouncesAtOnce586=== RUN TestLeadEndsOnShutdown587=== PAUSE TestLeadEndsOnShutdown588=== RUN TestLeadEndsWhenItsConnectionHangs5892026/11/03 08:17:22 INFO lead: acquired remote=192.0.2.1:12345902026-11-03 08:17:24.001 UTC [28508] FATAL: terminating connection due to administrator command5912026/11/03 08:17:24 INFO lead: acquired remote=192.0.2.1:12345922026/11/03 08:17:25 WARN lead: lock connection lost error="timeout: context deadline exceeded"5932026/11/03 08:17:25 INFO lead: released remote=192.0.2.1:12345942026/11/03 08:17:25 INFO lead: released remote=192.0.2.1:1234595--- PASS: TestLeadEndsWhenItsConnectionHangs (2.96s)596=== RUN TestGCAdvisoryLockBlocksConcurrentRun597=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun598=== RUN TestGCBugBareHashReferences599=== PAUSE TestGCBugBareHashReferences600=== RUN TestGCMetrics601=== PAUSE TestGCMetrics602=== RUN TestPushDedupSurvivesConcurrentGC603=== PAUSE TestPushDedupSurvivesConcurrentGC604=== RUN TestDeduplicatedObjectsRecordedAsPending605=== PAUSE TestDeduplicatedObjectsRecordedAsPending606=== RUN TestGCSweepSkipsPendingObjects607=== PAUSE TestGCSweepSkipsPendingObjects608=== RUN TestTombstonedObjectOfferedWithoutWaiting609=== PAUSE TestTombstonedObjectOfferedWithoutWaiting610=== RUN TestGCSweepDeliversEachKeyOnce611=== PAUSE TestGCSweepDeliversEachKeyOnce612=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection613=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection614=== RUN TestForceGCDuringPushOffersSweptObject615=== PAUSE TestForceGCDuringPushOffersSweptObject616=== RUN TestFailedS3DeleteKeepsTombstone617=== PAUSE TestFailedS3DeleteKeepsTombstone618=== RUN TestSweepSkipsRowsLockedByPush619=== PAUSE TestSweepSkipsRowsLockedByPush620=== RUN TestRegisterCompletedObjectNeedsPendingRow621=== PAUSE TestRegisterCompletedObjectNeedsPendingRow622=== RUN TestGetExistingObjectsLocksRows623=== PAUSE TestGetExistingObjectsLocksRows624=== RUN TestSweepRechecksPendingAfterLocking625=== PAUSE TestSweepRechecksPendingAfterLocking626=== RUN TestPushWaitsForSweepHoldingRow627=== PAUSE TestPushWaitsForSweepHoldingRow628=== RUN TestCommitRacingPendingCleanupKeepsObjects629=== PAUSE TestCommitRacingPendingCleanupKeepsObjects630=== RUN TestGCEndsOnShutdown631=== PAUSE TestGCEndsOnShutdown632=== RUN TestGCTaskStore_StartNew633=== PAUSE TestGCTaskStore_StartNew634=== RUN TestGCTaskStore_DeduplicateSameParams635=== PAUSE TestGCTaskStore_DeduplicateSameParams636=== RUN TestGCTaskStore_ConflictDifferentParams637=== PAUSE TestGCTaskStore_ConflictDifferentParams638=== RUN TestGCTaskStore_GetEmpty639=== PAUSE TestGCTaskStore_GetEmpty640=== RUN TestGCTaskStore_GetReturnsLatest641=== PAUSE TestGCTaskStore_GetReturnsLatest642=== RUN TestGCTaskStore_CompletedAllowsNewTask643=== PAUSE TestGCTaskStore_CompletedAllowsNewTask644=== RUN TestGCTaskStore_PhaseUpdates645=== PAUSE TestGCTaskStore_PhaseUpdates646=== RUN TestGCTaskStore_Fail647=== PAUSE TestGCTaskStore_Fail648=== RUN TestGracefulShutdownDrainsInflight649=== PAUSE TestGracefulShutdownDrainsInflight650=== RUN TestService_healthCheckHandler651=== PAUSE TestService_healthCheckHandler652=== RUN TestService_readinessHandler653=== PAUSE TestService_readinessHandler654=== RUN TestGenerateLandingPage655=== PAUSE TestGenerateLandingPage656=== RUN TestCacheConfigHandlerMaxNarSize657=== PAUSE TestCacheConfigHandlerMaxNarSize658=== RUN TestCreatePendingClosureRejectsOversizedNAR659=== PAUSE TestCreatePendingClosureRejectsOversizedNAR660=== RUN TestNARDeduplicationMetadataUploadBug661=== PAUSE TestNARDeduplicationMetadataUploadBug662=== RUN TestMetricsInventory663=== PAUSE TestMetricsInventory664=== RUN TestMetricsCommit665=== PAUSE TestMetricsCommit666=== RUN TestService_NativeMTLS667=== PAUSE TestService_NativeMTLS668=== RUN TestServerTLSConfig669=== PAUSE TestServerTLSConfig670=== RUN TestMultipartCleanup671=== PAUSE TestMultipartCleanup672=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded673=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded674=== RUN TestPendingCleanupUsesOneCutoff675=== PAUSE TestPendingCleanupUsesOneCutoff676=== RUN TestObjectStatsTrigger677=== PAUSE TestObjectStatsTrigger678=== RUN TestObjectStatsUpdatedOncePerCommit679=== PAUSE TestObjectStatsUpdatedOncePerCommit680=== RUN TestOrphanedObjectsGC681=== PAUSE TestOrphanedObjectsGC682=== RUN TestOrphanedObjectsGCStressTest683=== PAUSE TestOrphanedObjectsGCStressTest684=== RUN TestCreatePin_ReservedPins685=== PAUSE TestCreatePin_ReservedPins686=== RUN TestPresentReportsOnlyClosureRoots687=== PAUSE TestPresentReportsOnlyClosureRoots688=== RUN TestPresentRefreshesOnlyStaleClosures689=== PAUSE TestPresentRefreshesOnlyStaleClosures690=== RUN TestPresentNotReportedWhileGCDeletesClosure691=== PAUSE TestPresentNotReportedWhileGCDeletesClosure692=== RUN TestParseSingleRange693=== PAUSE TestParseSingleRange694=== RUN TestProxyHeadersOnlyTrustedOnSocket6952026/11/03 08:17:25 INFO Starting HTTP server address=127.0.0.1:509776962026/11/03 08:17:25 INFO Starting HTTP server address=proxy.sock6972026/11/03 08:17:25 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6982026/11/03 08:17:25 INFO Shutdown signal received, draining in-flight requests timeout=10s699--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.16s)700=== RUN TestIsValidCachePath701=== PAUSE TestIsValidCachePath702=== RUN TestReadProxyNarinfo703=== PAUSE TestReadProxyNarinfo704=== RUN TestReadProxyNarinfoAlreadyDecompressed705=== PAUSE TestReadProxyNarinfoAlreadyDecompressed706=== RUN TestReadProxyContentNegotiation707=== PAUSE TestReadProxyContentNegotiation708=== RUN TestReadProxyNarStreaming709=== PAUSE TestReadProxyNarStreaming710=== RUN TestReadProxy404711=== PAUSE TestReadProxy404712=== RUN TestReadProxyInvalidPath713=== PAUSE TestReadProxyInvalidPath714=== RUN TestReadProxyHead715=== PAUSE TestReadProxyHead716=== RUN TestReadProxyOutlastsServerWriteTimeout717=== PAUSE TestReadProxyOutlastsServerWriteTimeout718=== RUN TestReadProxyConditionalGet719=== PAUSE TestReadProxyConditionalGet720=== RUN TestReadProxyRootRedirectsToIndexHTML721=== PAUSE TestReadProxyRootRedirectsToIndexHTML722=== RUN TestReadProxyDisabled723=== PAUSE TestReadProxyDisabled724=== RUN TestReadRedirectNar725=== PAUSE TestReadRedirectNar726=== RUN TestReadRedirectKeepsNarinfoProxied727=== PAUSE TestReadRedirectKeepsNarinfoProxied728=== RUN TestReadProxyRangeRequest729=== PAUSE TestReadProxyRangeRequest730=== RUN TestReadRedirectUsesPublicS3URL731=== PAUSE TestReadRedirectUsesPublicS3URL732=== RUN TestPush_OverlappingRootsStoreOneRowPerKey733=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey734=== RUN TestPush_CompleteCommitsEveryRoot735=== PAUSE TestPush_CompleteCommitsEveryRoot736=== RUN TestPush_RepeatedRootCommitsOnce737=== PAUSE TestPush_RepeatedRootCommitsOnce738=== RUN TestPush_CompleteWaitsForCleanupOfThePush739=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush740=== RUN TestPush_RootsAreLockedInByteOrder741=== PAUSE TestPush_RootsAreLockedInByteOrder742=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit743=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit744=== RUN TestPush_RejectsBadRequests745=== PAUSE TestPush_RejectsBadRequests746=== RUN TestPush_SignsNarinfosOfItsPendingObjects747=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects748=== RUN TestRedundantMultipartUpload749=== PAUSE TestRedundantMultipartUpload750=== RUN TestCompleteMultipartUpload_ErrorButObjectExists751=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists752=== RUN TestCompletedNarNotReofferedAcrossClosures753=== PAUSE TestCompletedNarNotReofferedAcrossClosures754=== RUN TestPresignedUploadRegisteredBeforeCommit755=== PAUSE TestPresignedUploadRegisteredBeforeCommit756=== RUN TestService_Rustfstest757=== PAUSE TestService_Rustfstest758=== RUN TestParseSize759=== PAUSE TestParseSize760=== RUN TestSkippedUploadsHandler761=== PAUSE TestSkippedUploadsHandler762=== RUN TestSystemdListenerNotActivated763--- PASS: TestSystemdListenerNotActivated (0.00s)764=== RUN TestWatchdogBeatsWhenHealthy765--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)766=== RUN TestWatchdogSkipsWhenUnhealthy7672026/11/03 08:17:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7682026/11/03 08:17:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/11/03 08:17:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/03 08:17:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/03 08:17:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/03 08:17:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/03 08:17:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/03 08:17:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/03 08:17:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/11/03 08:17:25 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"777--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)778=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle779=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle780=== RUN TestProxyWriteTimeout781=== PAUSE TestProxyWriteTimeout782=== RUN TestPendingClosureWriteTimeout783=== PAUSE TestPendingClosureWriteTimeout784=== RUN TestIsValidUploadKey785=== PAUSE TestIsValidUploadKey786=== RUN TestUploadHandlersRejectInvalidKeys787=== PAUSE TestUploadHandlersRejectInvalidKeys788=== RUN TestUploadHandlersRejectOversizedBody789=== PAUSE TestUploadHandlersRejectOversizedBody790=== RUN TestService_cleanupPendingClosuresHandler791=== PAUSE TestService_cleanupPendingClosuresHandler792=== RUN TestService_createPendingClosureHandler793=== PAUSE TestService_createPendingClosureHandler794=== RUN TestService_verifyS3Integrity795=== PAUSE TestService_verifyS3Integrity796=== RUN TestService_verifyS3ReuploadsStaleNarinfo797=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo798=== RUN TestCompleteMultipartUnregistered799=== PAUSE TestCompleteMultipartUnregistered800=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT801=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT802=== CONT TestReadProxyContentNegotiation803=== CONT TestSweepSkipsRowsLockedByPush804=== CONT TestCacheConfigHandlerMaxNarSize805=== CONT TestPresentReportsOnlyClosureRoots806=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded807=== CONT TestDeleteClosuresRacingPins808--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)809=== CONT TestCreatePendingClosureRejectsOversizedNAR810=== CONT TestClientCADerivations811=== CONT TestService_AuthMiddleware812=== CONT TestGetExistingObjectsLocksRows813=== CONT TestReadProxyNarinfo814=== CONT TestRegisterCompletedObjectNeedsPendingRow815=== CONT TestParseSingleRange816=== RUN TestParseSingleRange/none817=== CONT TestIsValidCachePath818=== PAUSE TestParseSingleRange/none819=== RUN TestIsValidCachePath/narinfo820=== PAUSE TestIsValidCachePath/narinfo8212026/11/03 08:17:25 INFO Received uploads request method=POST path=/api/pending_closures822=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT823=== CONT TestCompleteMultipartUnregistered824=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars825--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)826=== CONT TestService_verifyS3Integrity827=== CONT TestService_createPendingClosureHandler828=== CONT TestService_cleanupPendingClosuresHandler829=== CONT TestUploadHandlersRejectOversizedBody830=== CONT TestUploadHandlersRejectInvalidKeys831=== CONT TestReadProxyNarinfoAlreadyDecompressed832=== CONT TestPresentNotReportedWhileGCDeletesClosure833=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale834=== CONT TestPresentRefreshesOnlyStaleClosures835=== RUN TestParseSingleRange/unknown_unit836=== CONT TestIsValidUploadKey837=== CONT TestService_verifyS3ReuploadsStaleNarinfo838=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars839=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info840=== PAUSE TestParseSingleRange/unknown_unit841=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info842=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale843=== RUN TestIsValidUploadKey/narinfo844=== PAUSE TestIsValidUploadKey/narinfo845=== RUN TestParseSingleRange/multi-range_ignored846=== PAUSE TestParseSingleRange/multi-range_ignored847=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed848=== RUN TestParseSingleRange/malformed_no_dash849=== PAUSE TestParseSingleRange/malformed_no_dash850=== RUN TestParseSingleRange/malformed_both_empty851=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed852=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed853=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh854=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal855=== RUN TestIsValidCachePath/nar_zst856=== RUN TestIsValidUploadKey/nar_zst857=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed858=== PAUSE TestParseSingleRange/malformed_both_empty859=== RUN TestParseSingleRange/malformed_end_before_start860=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh861=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost862=== PAUSE TestIsValidCachePath/nar_zst863=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal864=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key865=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key866=== CONT TestPendingClosureWriteTimeout867=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost868=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed869=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed870=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed871=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed872=== RUN TestIsValidCachePath/nar_xz873=== PAUSE TestIsValidCachePath/nar_xz874=== RUN TestIsValidCachePath/nar_bz2875=== PAUSE TestIsValidCachePath/nar_bz2876=== RUN TestIsValidCachePath/nar_uncompressed877=== PAUSE TestIsValidCachePath/nar_uncompressed878=== RUN TestIsValidCachePath/ls879=== PAUSE TestIsValidCachePath/ls880=== RUN TestIsValidCachePath/log881=== PAUSE TestIsValidCachePath/log882=== RUN TestIsValidCachePath/realisation883=== PAUSE TestIsValidCachePath/realisation884=== RUN TestIsValidCachePath/nix-cache-info885=== PAUSE TestIsValidCachePath/nix-cache-info886=== RUN TestIsValidCachePath/index.html887=== PAUSE TestIsValidCachePath/index.html888=== RUN TestIsValidCachePath/traversal_parent889=== PAUSE TestIsValidCachePath/traversal_parent890=== RUN TestIsValidCachePath/traversal_in_middle891=== PAUSE TestIsValidCachePath/traversal_in_middle892=== RUN TestIsValidCachePath/invalid_char_e893=== PAUSE TestIsValidCachePath/invalid_char_e894=== RUN TestIsValidCachePath/invalid_char_u895=== PAUSE TestIsValidCachePath/invalid_char_u896=== RUN TestIsValidCachePath/random_path897=== PAUSE TestIsValidCachePath/random_path898=== RUN TestIsValidCachePath/empty899=== PAUSE TestIsValidCachePath/empty900=== RUN TestIsValidCachePath/leading_slash901=== PAUSE TestIsValidCachePath/leading_slash902=== RUN TestIsValidCachePath/wrong_extension903=== PAUSE TestIsValidCachePath/wrong_extension904=== RUN TestIsValidCachePath/short_hash905=== PAUSE TestIsValidCachePath/short_hash906=== CONT TestProxyWriteTimeout907=== RUN TestProxyWriteTimeout/narinfo908=== PAUSE TestProxyWriteTimeout/narinfo909=== RUN TestProxyWriteTimeout/1_GiB_nar910=== PAUSE TestProxyWriteTimeout/1_GiB_nar911=== RUN TestProxyWriteTimeout/10_GiB_nar912=== PAUSE TestProxyWriteTimeout/10_GiB_nar913=== RUN TestProxyWriteTimeout/unknown_size914=== PAUSE TestProxyWriteTimeout/unknown_size915=== RUN TestPendingClosureWriteTimeout/empty916=== PAUSE TestPendingClosureWriteTimeout/empty917=== RUN TestPendingClosureWriteTimeout/400_objects918=== PAUSE TestPendingClosureWriteTimeout/400_objects919=== RUN TestPendingClosureWriteTimeout/670k_objects920=== PAUSE TestPendingClosureWriteTimeout/670k_objects921=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline922=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline923=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle924=== CONT TestSkippedUploadsHandler9252026/11/03 08:17:25 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000926--- PASS: TestSkippedUploadsHandler (0.00s)927=== CONT TestService_Rustfstest928=== CONT TestParseSize929--- PASS: TestParseSize (0.00s)930=== CONT TestPresignedUploadRegisteredBeforeCommit931=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key932=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key933=== PAUSE TestIsValidUploadKey/nar_zst934=== PAUSE TestParseSingleRange/malformed_end_before_start935=== RUN TestParseSingleRange/closed936=== PAUSE TestParseSingleRange/closed937=== RUN TestParseSingleRange/open-ended938=== PAUSE TestParseSingleRange/open-ended939=== RUN TestParseSingleRange/end_clamped_to_size940=== PAUSE TestParseSingleRange/end_clamped_to_size941=== RUN TestParseSingleRange/suffix942=== PAUSE TestParseSingleRange/suffix943=== RUN TestParseSingleRange/suffix_exceeds_size944=== PAUSE TestParseSingleRange/suffix_exceeds_size945=== RUN TestParseSingleRange/single_byte946=== PAUSE TestParseSingleRange/single_byte947=== RUN TestParseSingleRange/start_past_EOF948=== PAUSE TestParseSingleRange/start_past_EOF949=== RUN TestParseSingleRange/start_far_past_EOF950=== PAUSE TestParseSingleRange/start_far_past_EOF951=== CONT TestCompletedNarNotReofferedAcrossClosures952=== RUN TestIsValidUploadKey/nar_xz953=== PAUSE TestIsValidUploadKey/nar_xz954=== RUN TestIsValidUploadKey/nar_plain955=== PAUSE TestIsValidUploadKey/nar_plain956=== RUN TestIsValidUploadKey/listing957=== PAUSE TestIsValidUploadKey/listing958=== RUN TestIsValidUploadKey/build_log959=== PAUSE TestIsValidUploadKey/build_log960=== RUN TestIsValidUploadKey/build_log_home-manager_file961=== PAUSE TestIsValidUploadKey/build_log_home-manager_file962=== RUN TestIsValidUploadKey/build_log_plus_in_name963=== PAUSE TestIsValidUploadKey/build_log_plus_in_name964=== RUN TestIsValidUploadKey/build_log_question_mark965=== PAUSE TestIsValidUploadKey/build_log_question_mark966=== RUN TestIsValidUploadKey/build_log_equals967=== PAUSE TestIsValidUploadKey/build_log_equals968=== RUN TestIsValidUploadKey/realisation969=== PAUSE TestIsValidUploadKey/realisation970=== RUN TestIsValidUploadKey/realisation_plus_in_output971=== PAUSE TestIsValidUploadKey/realisation_plus_in_output972=== RUN TestIsValidUploadKey/nix-cache-info973=== PAUSE TestIsValidUploadKey/nix-cache-info974=== RUN TestIsValidUploadKey/index.html975=== PAUSE TestIsValidUploadKey/index.html976=== RUN TestIsValidUploadKey/narinfo_key,_nar_type977=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type978=== RUN TestIsValidUploadKey/nar_key,_narinfo_type979=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type980=== RUN TestIsValidUploadKey/listing_key,_narinfo_type981=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type982=== RUN TestIsValidUploadKey/traversal983=== PAUSE TestIsValidUploadKey/traversal984=== RUN TestIsValidUploadKey/traversal_nar985=== PAUSE TestIsValidUploadKey/traversal_nar986=== RUN TestIsValidUploadKey/absolute987=== PAUSE TestIsValidUploadKey/absolute988=== RUN TestIsValidUploadKey/empty_key989=== PAUSE TestIsValidUploadKey/empty_key990=== RUN TestIsValidUploadKey/unknown_type991=== PAUSE TestIsValidUploadKey/unknown_type992=== CONT TestCompleteMultipartUpload_ErrorButObjectExists993=== CONT TestRedundantMultipartUpload994=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure995=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure996=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart997=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart998=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts999=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts1000=== CONT TestPush_SignsNarinfosOfItsPendingObjects10012026/11/03 08:17:26 INFO Received uploads request method=POST path=/api/pending_closures1002--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (0.99s)1003=== CONT TestPush_RejectsBadRequests1004--- PASS: TestReadProxyContentNegotiation (1.32s)1005=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit1006--- PASS: TestPresentReportsOnlyClosureRoots (1.54s)1007=== CONT TestPush_RootsAreLockedInByteOrder10082026/11/03 08:17:27 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"1009--- PASS: TestService_AuthMiddleware (1.80s)1010=== CONT TestPush_CompleteWaitsForCleanupOfThePush10112026/11/03 08:17:28 INFO Aborted multipart uploads count=0 kept=010122026/11/03 08:17:28 WARN Force mode enabled - objects will be deleted immediately without grace period10132026/11/03 08:17:28 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=010142026/11/03 08:17:28 INFO Vacuumed table table=pending_closures10152026/11/03 08:17:28 INFO Vacuumed table table=pending_objects10162026/11/03 08:17:28 INFO Vacuumed table table=multipart_uploads10172026/11/03 08:17:28 INFO Vacuumed table table=closures10182026/11/03 08:17:28 INFO Vacuumed table table=objects10192026/11/03 08:17:28 INFO Aborted multipart uploads count=0 kept=010202026/11/03 08:17:28 WARN Force mode enabled - objects will be deleted immediately without grace period10212026/11/03 08:17:28 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10222026/11/03 08:17:28 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst1023--- PASS: TestCompleteMultipartUnregistered (2.33s)1024=== CONT TestPush_RepeatedRootCommitsOnce10252026/11/03 08:17:28 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=010262026/11/03 08:17:28 INFO Vacuumed table table=pending_closures10272026/11/03 08:17:28 INFO Vacuumed table table=pending_objects10282026/11/03 08:17:28 INFO Vacuumed table table=multipart_uploads10292026/11/03 08:17:28 INFO Vacuumed table table=closures10302026/11/03 08:17:28 INFO Vacuumed table table=objects1031--- PASS: TestSweepSkipsRowsLockedByPush (2.43s)1032=== CONT TestPush_CompleteCommitsEveryRoot10332026/11/03 08:17:28 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1034--- PASS: TestReadProxyNarinfo (2.60s)1035=== CONT TestPush_OverlappingRootsStoreOneRowPerKey10362026/11/03 08:17:28 INFO Received cleanup request method=DELETE path=/api/pending_closures10372026/11/03 08:17:28 INFO Aborted multipart uploads count=0 kept=010382026/11/03 08:17:28 INFO Received uploads request method=POST path=/api/pending_closures10392026/11/03 08:17:28 INFO Received cleanup request method=DELETE path=/api/pending_closures10402026/11/03 08:17:28 INFO Aborted multipart uploads count=1 kept=010412026/11/03 08:17:28 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10422026-11-03 08:17:28.650 UTC [28579] ERROR: Closure does not exist: id=110432026-11-03 08:17:28.650 UTC [28579] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10442026-11-03 08:17:28.650 UTC [28579] STATEMENT: -- name: CommitPendingClosure :one1045 SELECT commit_pending_closure($1::bigint)::bigint1046 1047--- PASS: TestService_cleanupPendingClosuresHandler (2.84s)1048=== CONT TestReadRedirectUsesPublicS3URL10492026/11/03 08:17:28 INFO Received uploads request method=POST path=/api/pending_closures10502026/11/03 08:17:29 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1051--- PASS: TestPresentRefreshesOnlyStaleClosures (3.21s)1052=== CONT TestReadProxyRangeRequest10532026/11/03 08:17:29 INFO Received uploads request method=POST path=/api/pending_closures10542026/11/03 08:17:29 INFO Received uploads request method=POST path=/api/pending_closures10552026/11/03 08:17:29 INFO Received uploads request method=POST path=/api/pending_closures10562026/11/03 08:17:29 INFO Received uploads request method=POST path=/api/pending_closures10572026/11/03 08:17:29 INFO Received uploads request method=POST path=/api/pending_closures1058--- PASS: TestDeleteClosuresRacingPins (3.95s)1059=== CONT TestReadRedirectKeepsNarinfoProxied1060--- PASS: TestRegisterCompletedObjectNeedsPendingRow (4.02s)1061=== CONT TestReadRedirectNar1062=== NAME TestClientCADerivations1063 client_ca_test.go:136: Built CA derivation: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientCADerivations1927765048/001/store/75pai1a2az4gpyyh4533143b2jki7nfy-ca-test1064 client_ca_test.go:139: Found 1 dependencies (including self)10652026/11/03 08:17:30 INFO Received push request method=POST path=/api/pushes10662026/11/03 08:17:30 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)10672026/11/03 08:17:30 INFO Uploading 75pai1a2az4gpyyh4533143b2jki7nfy-ca-test (144B)1068--- PASS: TestGetExistingObjectsLocksRows (4.31s)1069=== CONT TestReadProxyDisabled10702026/11/03 08:17:30 WARN Failed to register uploaded object key=75pai1a2az4gpyyh4533143b2jki7nfy.ls error="server returned 404: 404 page not found\n"10712026/11/03 08:17:30 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"10722026/11/03 08:17:30 WARN Failed to register uploaded object key=log/9li8g81pjjp2csd22k9y7fhcx1m0sid4-ca-test.drv error="server returned 404: 404 page not found\n"10732026/11/03 08:17:30 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign10742026/11/03 08:17:30 INFO Signed narinfos id=1 count=110752026/11/03 08:17:30 INFO Uploading 1 narinfos10762026/11/03 08:17:30 INFO Received complete push request method=POST path=/api/pushes/1/complete10772026/11/03 08:17:30 WARN Failed to register uploaded object key=75pai1a2az4gpyyh4533143b2jki7nfy.narinfo error="server returned 404: 404 page not found\n"10782026/11/03 08:17:30 INFO Completed push id=1 objects=4 duration=15.695583ms10792026/11/03 08:17:30 INFO Upload complete. (300ms)1080=== NAME TestClientCADerivations1081 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientCADerivations1927765048/001/store/75pai1a2az4gpyyh4533143b2jki7nfy-ca-test1082 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1083 Compression: zstd1084 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1085 NarSize: 1441086 References: 1087 Deriver: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientCADerivations1927765048/001/store/9li8g81pjjp2csd22k9y7fhcx1m0sid4-ca-test.drv1088 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1089 client_ca_test.go:185: Checking for realisation files in S3...1090 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1091 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1092 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket15?endpoint=http://localhost:50917®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientCADerivations1927765048/001/store'1093 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11094--- PASS: TestReadProxyNarinfoAlreadyDecompressed (4.61s)1095=== CONT TestReadProxyRootRedirectsToIndexHTML1096--- PASS: TestClientCADerivations (4.69s)1097=== CONT TestReadProxyConditionalGet10982026/11/03 08:17:30 INFO Received uploads request method=POST path=/api/pending_closures10992026/11/03 08:17:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11002026/11/03 08:17:30 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11012026/11/03 08:17:30 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjM0YTliZDFmLWIyNGItNDcwOS04ZjNhLTNhMDhkNzZmODliYXgxNzkzNjkzODQ5MzY3OTkzMDAw parts=1211022026/11/03 08:17:30 INFO Received uploads request method=POST path=/api/pending_closures11032026/11/03 08:17:30 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjI5OWJkM2Y4LWU2OWItNGExMi04MzhlLWE5OTBjMGZiMjE2ZHgxNzkzNjkzODQ5NjYwMTUxMDAw parts=1011042026/11/03 08:17:30 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11052026/11/03 08:17:30 INFO Received uploads request method=POST path=/api/pending_closures11062026/11/03 08:17:30 INFO Completed upload id=1 objects=2 duration=6.9635ms11072026/11/03 08:17:30 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000011082026/11/03 08:17:30 INFO Received uploads request method=POST path=/api/pending_closures11092026/11/03 08:17:30 INFO Starting cleanup of old closures method=DELETE path=/api/closures11102026/11/03 08:17:30 INFO Received uploads request method=POST path=/api/pending_closures11112026/11/03 08:17:31 INFO Aborted multipart uploads count=0 kept=011122026/11/03 08:17:31 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=01113--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (5.25s)1114=== CONT TestReadProxyOutlastsServerWriteTimeout11152026/11/03 08:17:31 INFO Vacuumed table table=pending_closures11162026/11/03 08:17:31 INFO Vacuumed table table=pending_objects11172026/11/03 08:17:31 INFO Vacuumed table table=multipart_uploads11182026/11/03 08:17:31 INFO Vacuumed table table=closures11192026/11/03 08:17:31 INFO Vacuumed table table=objects11202026/11/03 08:17:31 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001121--- PASS: TestService_createPendingClosureHandler (5.45s)11222026/11/03 08:17:31 INFO Received uploads request method=POST path=/api/pending_closures1123=== CONT TestReadProxyHead1124--- PASS: TestService_Rustfstest (5.70s)1125=== CONT TestReadProxyInvalidPath11262026/11/03 08:17:31 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11272026/11/03 08:17:31 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjdkOGZkOGQ3LWQ5ZmItNGI0ZC04MmJlLWY0Mjk0OTI4ZDc5OHgxNzkzNjkzODUxMzIzMjA1MDAw11282026/11/03 08:17:31 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjdkOGZkOGQ3LWQ5ZmItNGI0ZC04MmJlLWY0Mjk0OTI4ZDc5OHgxNzkzNjkzODUxMzIzMjA1MDAw parts=11129--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (5.77s)1130=== CONT TestReadProxy40411312026/11/03 08:17:31 INFO Received uploads request method=POST path=/api/pending_closures11322026/11/03 08:17:32 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst11332026/11/03 08:17:32 INFO Received uploads request method=POST path=/api/pending_closures1134--- PASS: TestPresignedUploadRegisteredBeforeCommit (6.15s)1135=== CONT TestReadProxyNarStreaming11362026/11/03 08:17:32 INFO Received uploads request method=POST path=/api/pending_closures11372026/11/03 08:17:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11382026/11/03 08:17:32 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjc4MmUzZTgxLTE1YjAtNDdjNi1iZmM0LWFiOGQwODRkYjQ4ZngxNzkzNjkzODUwNzIxNDQyMDAw parts=1011392026/11/03 08:17:32 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete11402026/11/03 08:17:32 INFO Completed upload id=1 objects=2 duration=33.243959ms11412026/11/03 08:17:32 INFO Received uploads request method=POST path=/api/pending_closures11422026/11/03 08:17:32 INFO Received uploads request method=POST path=/api/pending_closures11432026/11/03 08:17:32 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo11442026/11/03 08:17:32 WARN Found objects in DB but missing from S3, will re-upload count=11145--- PASS: TestService_verifyS3Integrity (6.67s)1146=== CONT TestClientSharedPathCommittedMidPush11472026/11/03 08:17:32 INFO Received push request method=POST path=/api/pushes11482026/11/03 08:17:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11492026/11/03 08:17:32 INFO Signed narinfos id=1 count=111502026/11/03 08:17:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11512026/11/03 08:17:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11522026/11/03 08:17:32 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"11532026/11/03 08:17:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11542026/11/03 08:17:32 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"11552026/11/03 08:17:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11562026/11/03 08:17:32 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=111572026/11/03 08:17:32 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11582026/11/03 08:17:32 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1159--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (6.85s)1160=== CONT TestClientFallsBackToClosures11612026/11/03 08:17:32 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11622026/11/03 08:17:33 INFO Received push request method=POST path=/api/pushes11632026/11/03 08:17:33 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLmM0NmFiMTE0LTEwY2YtNDg0YS05M2NhLTgxZWE3NjRmMTgyZHgxNzkzNjkzODUxMDA2MTQxMDAw error="Get \"http://127.0.0.1:1/bucket16/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"11642026/11/03 08:17:33 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjQ2MWUxMzM5LTQxNzktNDc4MS04MjBlLWM5NDE3OWM2ZmE3NHgxNzkzNjkzODUwOTYwMDE1MDAw parts=1211652026/11/03 08:17:33 INFO Received cleanup request method=DELETE path=/api/pending_closures11662026/11/03 08:17:33 INFO Aborted multipart uploads count=1 kept=01167--- PASS: TestRedundantMultipartUpload (7.22s)1168=== CONT TestClientPushesUseOnePush1169=== RUN TestPush_RejectsBadRequests/no_roots1170=== PAUSE TestPush_RejectsBadRequests/no_roots1171=== RUN TestPush_RejectsBadRequests/no_objects1172=== PAUSE TestPush_RejectsBadRequests/no_objects1173=== RUN TestPush_RejectsBadRequests/bad_root1174=== PAUSE TestPush_RejectsBadRequests/bad_root1175=== RUN TestPush_RejectsBadRequests/root_not_in_objects1176=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1177=== CONT TestPinProtectsFromGC11782026-11-03 08:17:33.517 UTC [28663] ERROR: Push does not exist: id=111792026-11-03 08:17:33.517 UTC [28663] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE11802026-11-03 08:17:33.517 UTC [28663] STATEMENT: SELECT commit_push($1)1181--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (5.91s)1182=== CONT TestFailedS3DeleteKeepsTombstone11832026/11/03 08:17:33 WARN Rate limiter enabled after throttle name=s3-test rate=511842026/11/03 08:17:33 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1185=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1186 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101187 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001188--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (7.66s)1189=== CONT TestForceGCDuringPushOffersSweptObject1190=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1191=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1192=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1193=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1194=== CONT TestGCTaskStore_GetReturnsLatest1195--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1196=== CONT TestGenerateLandingPage1197--- PASS: TestGenerateLandingPage (0.00s)1198=== CONT TestService_readinessHandler11992026/11/03 08:17:33 INFO Received push request method=POST path=/api/pushes12002026/11/03 08:17:33 INFO Received complete push request method=POST path=/api/pushes/1/complete12012026/11/03 08:17:33 INFO Completed push id=1 objects=4 duration=52.593625ms12022026/11/03 08:17:33 INFO Received push request method=POST path=/api/pushes12032026/11/03 08:17:34 INFO Aborted multipart uploads count=0 kept=012042026/11/03 08:17:34 WARN Force mode enabled - objects will be deleted immediately without grace period12052026/11/03 08:17:34 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=012062026/11/03 08:17:34 INFO Received push request method=POST path=/api/pushes12072026/11/03 08:17:34 INFO Vacuumed table table=pending_closures12082026/11/03 08:17:34 INFO Vacuumed table table=pending_objects12092026/11/03 08:17:34 INFO Vacuumed table table=multipart_uploads12102026/11/03 08:17:34 INFO Vacuumed table table=closures12112026-11-03 08:17:34.313 UTC [28674] ERROR: could not obtain lock on row in relation "closures"12122026-11-03 08:17:34.313 UTC [28674] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12132026-11-03 08:17:34.316 UTC [28674] ERROR: could not obtain lock on row in relation "closures"12142026-11-03 08:17:34.316 UTC [28674] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12152026-11-03 08:17:34.324 UTC [28674] ERROR: could not obtain lock on row in relation "closures"12162026-11-03 08:17:34.324 UTC [28674] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12172026/11/03 08:17:34 INFO Vacuumed table table=objects12182026-11-03 08:17:34.329 UTC [28674] ERROR: could not obtain lock on row in relation "closures"12192026-11-03 08:17:34.329 UTC [28674] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12202026-11-03 08:17:34.330 UTC [28674] ERROR: could not obtain lock on row in relation "closures"12212026-11-03 08:17:34.330 UTC [28674] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT12222026/11/03 08:17:34 INFO Received complete push request method=POST path=/api/pushes/2/complete12232026/11/03 08:17:34 INFO Completed push id=2 objects=4 duration=8.375084ms1224--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (7.21s)1225=== CONT TestService_healthCheckHandler1226--- PASS: TestPush_RootsAreLockedInByteOrder (6.99s)1227=== CONT TestGracefulShutdownDrainsInflight12282026/11/03 08:17:34 INFO Starting HTTP server address=127.0.0.1:5108912292026/11/03 08:17:34 INFO Shutdown signal received, draining in-flight requests timeout=10s1230--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1231=== CONT TestGCTaskStore_Fail1232--- PASS: TestGCTaskStore_Fail (0.00s)1233=== CONT TestGCTaskStore_PhaseUpdates1234--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1235=== CONT TestGCTaskStore_CompletedAllowsNewTask1236--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1237=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection12382026/11/03 08:17:34 INFO Received push request method=POST path=/api/pushes12392026/11/03 08:17:34 INFO Received complete multipart upload request method=POST path=/api/multipart/complete12402026/11/03 08:17:34 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjUzMDIyZDhkLTNmNjgtNDM3ZC04NTc5LTMyNjEzNTAyZDY2MXgxNzkzNjkzODUyMzY1NDQwMDAw parts=1212412026/11/03 08:17:34 INFO Received complete push request method=POST path=/api/pushes/1/complete12422026/11/03 08:17:34 INFO Received uploads request method=POST path=/api/pending_closures1243=== CONT TestGCSweepDeliversEachKeyOnce1244--- PASS: TestCompletedNarNotReofferedAcrossClosures (8.71s)12452026/11/03 08:17:34 INFO Completed push id=1 objects=4 duration=26.8565ms1246--- PASS: TestPush_RepeatedRootCommitsOnce (6.52s)1247=== CONT TestTombstonedObjectOfferedWithoutWaiting12482026/11/03 08:17:34 INFO Received push request method=POST path=/api/pushes12492026/11/03 08:17:34 INFO Received complete push request method=POST path=/api/pushes/1/complete12502026/11/03 08:17:35 INFO Completed push id=1 objects=6 duration=67.856042ms1251--- PASS: TestPush_CompleteCommitsEveryRoot (6.83s)1252=== CONT TestGCSweepSkipsPendingObjects12532026/11/03 08:17:35 INFO Received push request method=POST path=/api/pushes1254--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (6.97s)1255=== CONT TestService_RequireScope_OIDC12562026/11/03 08:17:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51107/oidc1257--- PASS: TestReadRedirectUsesPublicS3URL (7.01s)1258=== CONT TestCreatePin_ReservedPins12592026/11/03 08:17:35 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51113/oidc1260--- PASS: TestReadProxyRangeRequest (6.86s)1261=== CONT TestDeduplicatedObjectsRecordedAsPending1262--- PASS: TestReadRedirectNar (6.33s)1263=== CONT TestPushDedupSurvivesConcurrentGC1264--- PASS: TestReadRedirectKeepsNarinfoProxied (6.69s)1265=== CONT TestGCMetrics1266--- PASS: TestReadProxyDisabled (6.62s)1267=== CONT TestGCBugBareHashReferences1268--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.65s)1269=== CONT TestGCAdvisoryLockBlocksConcurrentRun1270--- PASS: TestReadProxyConditionalGet (6.87s)1271=== CONT TestLeadEndsOnShutdown1272--- PASS: TestReadProxyHead (6.76s)1273=== CONT TestLeadIncumbentAnnouncesAtOnce1274--- PASS: TestReadProxyInvalidPath (6.51s)1275=== CONT TestCacheStatsHandler1276--- PASS: TestReadProxyNarStreaming (6.56s)1277=== CONT TestLeadElectsOneAndHandsOver1278--- PASS: TestReadProxy404 (7.00s)1279=== CONT TestCacheConfigHandler1280=== RUN TestCacheConfigHandler/full_config,_no_issuer1281=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1282=== RUN TestCacheConfigHandler/no_cache_url_configured1283=== PAUSE TestCacheConfigHandler/no_cache_url_configured1284=== RUN TestCacheConfigHandler/no_signing_keys1285=== PAUSE TestCacheConfigHandler/no_signing_keys1286=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1287=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1288=== CONT TestService_ReadScope_PublicByDefault12892026/11/03 08:17:39 INFO Received push request method=POST path=/api/pushes12902026/11/03 08:17:39 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)12912026/11/03 08:17:39 INFO Uploading skclaqmbnmc1y0ap50s2ykdkyms7ds7v-shared-dep (136B)12922026/11/03 08:17:39 INFO Uploading m0cznv9nsbhs8jjwx75l98qcl3azpr5g-top (264B)12932026/11/03 08:17:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"12942026/11/03 08:17:39 WARN Failed to register uploaded object key=nar/0m7sja29yg4is3d6yzc77q1dq71lv8jbnx6jzc8jgbipibb5wx37.nar.zst error="server returned 404: 404 page not found\n"12952026/11/03 08:17:39 WARN Failed to register uploaded object key=m0cznv9nsbhs8jjwx75l98qcl3azpr5g.ls error="server returned 404: 404 page not found\n"12962026/11/03 08:17:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12972026/11/03 08:17:39 WARN Failed to register uploaded object key=skclaqmbnmc1y0ap50s2ykdkyms7ds7v.ls error="server returned 404: 404 page not found\n"12982026/11/03 08:17:39 INFO Signed narinfos id=1 count=212992026/11/03 08:17:39 INFO Uploading 2 narinfos13002026/11/03 08:17:39 WARN Failed to register uploaded object key=m0cznv9nsbhs8jjwx75l98qcl3azpr5g.narinfo error="server returned 404: 404 page not found\n"13012026/11/03 08:17:39 INFO Received complete push request method=POST path=/api/pushes/1/complete13022026/11/03 08:17:39 WARN Failed to register uploaded object key=skclaqmbnmc1y0ap50s2ykdkyms7ds7v.narinfo error="server returned 404: 404 page not found\n"13032026/11/03 08:17:39 INFO Completed push id=1 objects=6 duration=6.3635ms13042026/11/03 08:17:39 INFO Upload complete. (183ms)1305=== NAME TestClientSharedPathCommittedMidPush1306 client_integration_test.go:727: Retrieved narinfo from S3:1307 StorePath: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientSharedPathCommittedMidPush351054300/001/store/skclaqmbnmc1y0ap50s2ykdkyms7ds7v-shared-dep1308 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1309 Compression: zstd1310 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821311 NarSize: 1361312 References: 1313 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1314 client_integration_test.go:727: Retrieved narinfo from S3:1315 StorePath: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientSharedPathCommittedMidPush351054300/001/store/m0cznv9nsbhs8jjwx75l98qcl3azpr5g-top1316 URL: nar/0m7sja29yg4is3d6yzc77q1dq71lv8jbnx6jzc8jgbipibb5wx37.nar.zst1317 Compression: zstd1318 NarHash: sha256:0m7sja29yg4is3d6yzc77q1dq71lv8jbnx6jzc8jgbipibb5wx371319 NarSize: 2641320 References: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientSharedPathCommittedMidPush351054300/001/store/skclaqmbnmc1y0ap50s2ykdkyms7ds7v-shared-dep1321 CA: text:sha256:16hxlq0fy2pyq9hzs8j3fzkpiwmvxv3h81pjvkg3vy5paww7fz931322--- PASS: TestClientSharedPathCommittedMidPush (6.81s)1323=== CONT TestConnectWaitsForAPeerMigration13242026/11/03 08:17:39 INFO Received uploads request method=POST path=/api/pending_closures13252026/11/03 08:17:39 INFO Received uploads request method=POST path=/api/pending_closures13262026/11/03 08:17:39 INFO Received uploads request method=POST path=/api/pending_closures13272026/11/03 08:17:39 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13282026/11/03 08:17:39 INFO Uploading lk1czwm22kd0vidhgpl1r81fnzfg1k8g-shared-dep (136B)13292026/11/03 08:17:39 INFO Uploading p083qyf73m79ains5r1rv96fj5ff49dg-b (256B)13302026/11/03 08:17:39 WARN Failed to register uploaded object key=16b4hw9zm3vr6rk5hmcv68vknz2l0j3b.ls error="server returned 404: 404 page not found\n"13312026/11/03 08:17:39 WARN Failed to register uploaded object key=nar/1ijn2mask533cca2n1rjv8dj8zc85wib9hrpbdkb7x4iw2np018v.nar.zst error="server returned 404: 404 page not found\n"13322026/11/03 08:17:39 WARN Failed to register uploaded object key=p083qyf73m79ains5r1rv96fj5ff49dg.ls error="server returned 404: 404 page not found\n"13332026/11/03 08:17:39 WARN Failed to register uploaded object key=lk1czwm22kd0vidhgpl1r81fnzfg1k8g.ls error="server returned 404: 404 page not found\n"13342026/11/03 08:17:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign13352026/11/03 08:17:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13362026/11/03 08:17:39 INFO Signed narinfos id=1 count=213372026/11/03 08:17:39 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign13382026/11/03 08:17:39 INFO Signed narinfos id=2 count=213392026/11/03 08:17:39 INFO Uploading 4 narinfos13402026/11/03 08:17:39 WARN Failed to register uploaded object key=lk1czwm22kd0vidhgpl1r81fnzfg1k8g.narinfo error="server returned 404: 404 page not found\n"13412026/11/03 08:17:39 WARN Failed to register uploaded object key=p083qyf73m79ains5r1rv96fj5ff49dg.narinfo error="server returned 404: 404 page not found\n"13422026/11/03 08:17:39 WARN Failed to register uploaded object key=16b4hw9zm3vr6rk5hmcv68vknz2l0j3b.narinfo error="server returned 404: 404 page not found\n"13432026/11/03 08:17:39 INFO Received push request method=POST path=/api/pushes13442026/11/03 08:17:39 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete13452026/11/03 08:17:39 WARN Failed to register uploaded object key=lk1czwm22kd0vidhgpl1r81fnzfg1k8g.narinfo error="server returned 404: 404 page not found\n"13462026/11/03 08:17:39 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)13472026/11/03 08:17:39 INFO Uploading nrl3sxzsfj6ccnj33za8vnznyrpvl3c8-b (256B)13482026/11/03 08:17:39 INFO Uploading vpng9xk5xwhrrz071pka3mpa0fcrlpnp-shared-dep (136B)13492026/11/03 08:17:39 INFO Completed upload id=1 objects=6 duration=13.545625ms13502026/11/03 08:17:39 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete13512026/11/03 08:17:39 INFO Completed upload id=2 objects=6 duration=355.875µs13522026/11/03 08:17:39 INFO Upload complete. (313ms)1353=== NAME TestClientFallsBackToClosures1354 client_pushes_test.go:112: Retrieved narinfo from S3:1355 StorePath: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientFallsBackToClosures2552996664/001/store/lk1czwm22kd0vidhgpl1r81fnzfg1k8g-shared-dep1356 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1357 Compression: zstd1358 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821359 NarSize: 1361360 References: 1361 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1362 client_pushes_test.go:112: Retrieved narinfo from S3:1363 StorePath: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientFallsBackToClosures2552996664/001/store/16b4hw9zm3vr6rk5hmcv68vknz2l0j3b-a1364 URL: nar/1ijn2mask533cca2n1rjv8dj8zc85wib9hrpbdkb7x4iw2np018v.nar.zst1365 Compression: zstd1366 NarHash: sha256:1ijn2mask533cca2n1rjv8dj8zc85wib9hrpbdkb7x4iw2np018v13672026/11/03 08:17:39 WARN Failed to register uploaded object key=m0l8lsk2y6bg5xnihsim9mgb7lmmnfc9.ls error="server returned 404: 404 page not found\n"1368 NarSize: 2561369 References: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientFallsBackToClosures2552996664/001/store/lk1czwm22kd0vidhgpl1r81fnzfg1k8g-shared-dep1370 CA: text:sha256:0jvg6w23175ra3y4zdrvb0zqjmihnsnak8d8bnn9nwlyjkdgah7r13712026/11/03 08:17:39 WARN Failed to register uploaded object key=vpng9xk5xwhrrz071pka3mpa0fcrlpnp.ls error="server returned 404: 404 page not found\n"1372 client_pushes_test.go:112: Retrieved narinfo from S3:1373 StorePath: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientFallsBackToClosures2552996664/001/store/p083qyf73m79ains5r1rv96fj5ff49dg-b1374 URL: nar/1ijn2mask533cca2n1rjv8dj8zc85wib9hrpbdkb7x4iw2np018v.nar.zst1375 Compression: zstd1376 NarHash: sha256:1ijn2mask533cca2n1rjv8dj8zc85wib9hrpbdkb7x4iw2np018v1377 NarSize: 2561378 References: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientFallsBackToClosures2552996664/001/store/lk1czwm22kd0vidhgpl1r81fnzfg1k8g-shared-dep1379 CA: text:sha256:0jvg6w23175ra3y4zdrvb0zqjmihnsnak8d8bnn9nwlyjkdgah7r13802026/11/03 08:17:39 WARN Failed to register uploaded object key=nar/0pzdav7kw8nd8vyd0fp7js9fzqj84xkcvkxl1nmaszk6gvipqk1y.nar.zst error="server returned 404: 404 page not found\n"13812026/11/03 08:17:39 INFO Aborted multipart uploads count=0 kept=013822026/11/03 08:17:39 WARN Failed to register uploaded object key=nrl3sxzsfj6ccnj33za8vnznyrpvl3c8.ls error="server returned 404: 404 page not found\n"13832026/11/03 08:17:39 WARN Force mode enabled - objects will be deleted immediately without grace period13842026/11/03 08:17:39 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign13852026/11/03 08:17:39 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"13862026/11/03 08:17:39 INFO Signed narinfos id=1 count=313872026/11/03 08:17:39 INFO Uploading 3 narinfos13882026/11/03 08:17:39 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."13892026/11/03 08:17:39 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1390--- PASS: TestFailedS3DeleteKeepsTombstone (6.12s)1391=== CONT TestObjectStatsUpdatedOncePerCommit13922026/11/03 08:17:39 WARN Failed to register uploaded object key=nrl3sxzsfj6ccnj33za8vnznyrpvl3c8.narinfo error="server returned 404: 404 page not found\n"1393--- PASS: TestClientFallsBackToClosures (6.83s)13942026/11/03 08:17:39 WARN Failed to register uploaded object key=vpng9xk5xwhrrz071pka3mpa0fcrlpnp.narinfo error="server returned 404: 404 page not found\n"1395=== CONT TestOrphanedObjectsGC13962026/11/03 08:17:39 INFO Received complete push request method=POST path=/api/pushes/1/complete13972026/11/03 08:17:39 WARN Failed to register uploaded object key=m0l8lsk2y6bg5xnihsim9mgb7lmmnfc9.narinfo error="server returned 404: 404 page not found\n"13982026/11/03 08:17:39 INFO Completed push id=1 objects=8 duration=8.990708ms13992026/11/03 08:17:39 INFO Upload complete. (259ms)1400=== NAME TestClientPushesUseOnePush1401 client_pushes_test.go:97: Retrieved narinfo from S3:1402 StorePath: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientPushesUseOnePush1884807278/001/store/vpng9xk5xwhrrz071pka3mpa0fcrlpnp-shared-dep1403 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1404 Compression: zstd1405 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821406 NarSize: 1361407 References: 1408 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1409 client_pushes_test.go:97: Retrieved narinfo from S3:1410 StorePath: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientPushesUseOnePush1884807278/001/store/m0l8lsk2y6bg5xnihsim9mgb7lmmnfc9-a1411 URL: nar/0pzdav7kw8nd8vyd0fp7js9fzqj84xkcvkxl1nmaszk6gvipqk1y.nar.zst1412 Compression: zstd1413 NarHash: sha256:0pzdav7kw8nd8vyd0fp7js9fzqj84xkcvkxl1nmaszk6gvipqk1y1414 NarSize: 2561415 References: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientPushesUseOnePush1884807278/001/store/vpng9xk5xwhrrz071pka3mpa0fcrlpnp-shared-dep1416 CA: text:sha256:128bkanwr2yinwj19dfyx0rp7p1qq2hfs4wvmj9b3ca32ld1agbk1417 client_pushes_test.go:97: Retrieved narinfo from S3:1418 StorePath: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientPushesUseOnePush1884807278/001/store/nrl3sxzsfj6ccnj33za8vnznyrpvl3c8-b1419 URL: nar/0pzdav7kw8nd8vyd0fp7js9fzqj84xkcvkxl1nmaszk6gvipqk1y.nar.zst1420 Compression: zstd1421 NarHash: sha256:0pzdav7kw8nd8vyd0fp7js9fzqj84xkcvkxl1nmaszk6gvipqk1y1422 NarSize: 2561423 References: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientPushesUseOnePush1884807278/001/store/vpng9xk5xwhrrz071pka3mpa0fcrlpnp-shared-dep1424 CA: text:sha256:128bkanwr2yinwj19dfyx0rp7p1qq2hfs4wvmj9b3ca32ld1agbk1425--- PASS: TestClientPushesUseOnePush (6.59s)1426=== CONT TestOrphanedObjectsGCStressTest14272026/11/03 08:17:39 WARN readiness check failed error="closed pool"1428--- PASS: TestService_readinessHandler (6.28s)1429=== CONT TestObjectStatsTrigger1430=== NAME TestPinProtectsFromGC1431 client_integration_test.go:778: Pinned store path: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestPinProtectsFromGC2479957452/001/store/bwq5m2ilxx1m0qzcf6jjbvbjhfjdh2l7-pinned-file.txt1432 client_integration_test.go:779: Unpinned store path: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestPinProtectsFromGC2479957452/001/store/i9mz6np1hlv4jz3llzxy4rcawsj8hzxy-unpinned-file.txt14332026/11/03 08:17:39 INFO Received push request method=POST path=/api/pushes1434--- PASS: TestService_healthCheckHandler (5.64s)1435=== CONT TestPendingCleanupUsesOneCutoff14362026/11/03 08:17:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14372026/11/03 08:17:40 INFO Uploading bwq5m2ilxx1m0qzcf6jjbvbjhfjdh2l7-pinned-file.txt (128B)14382026/11/03 08:17:40 WARN Failed to register uploaded object key=bwq5m2ilxx1m0qzcf6jjbvbjhfjdh2l7.ls error="server returned 404: 404 page not found\n"14392026/11/03 08:17:40 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14402026/11/03 08:17:40 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14412026/11/03 08:17:40 INFO Signed narinfos id=1 count=114422026/11/03 08:17:40 INFO Uploading 1 narinfos14432026/11/03 08:17:40 INFO Received complete push request method=POST path=/api/pushes/1/complete14442026/11/03 08:17:40 WARN Failed to register uploaded object key=bwq5m2ilxx1m0qzcf6jjbvbjhfjdh2l7.narinfo error="server returned 404: 404 page not found\n"14452026/11/03 08:17:40 INFO Completed push id=1 objects=3 duration=11.471208ms14462026/11/03 08:17:40 INFO Upload complete. (178ms)14472026/11/03 08:17:40 INFO Received uploads request method=POST path=/api/pending_closures14482026/11/03 08:17:40 INFO Received push request method=POST path=/api/pushes14492026/11/03 08:17:40 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14502026/11/03 08:17:40 INFO Uploading i9mz6np1hlv4jz3llzxy4rcawsj8hzxy-unpinned-file.txt (128B)14512026/11/03 08:17:40 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"14522026/11/03 08:17:40 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign14532026/11/03 08:17:40 WARN Failed to register uploaded object key=i9mz6np1hlv4jz3llzxy4rcawsj8hzxy.ls error="server returned 404: 404 page not found\n"14542026/11/03 08:17:40 INFO Signed narinfos id=2 count=114552026/11/03 08:17:40 INFO Uploading 1 narinfos14562026/11/03 08:17:40 INFO Received complete push request method=POST path=/api/pushes/2/complete14572026/11/03 08:17:40 WARN Failed to register uploaded object key=i9mz6np1hlv4jz3llzxy4rcawsj8hzxy.narinfo error="server returned 404: 404 page not found\n"14582026/11/03 08:17:40 INFO Completed push id=2 objects=3 duration=1.103875ms14592026/11/03 08:17:40 INFO Upload complete. (143ms)14602026/11/03 08:17:40 INFO Starting cleanup of old closures method=DELETE path=/api/closures14612026/11/03 08:17:40 INFO Garbage collection started14622026/11/03 08:17:40 INFO Aborted multipart uploads count=0 kept=014632026/11/03 08:17:40 WARN Force mode enabled - objects will be deleted immediately without grace period14642026/11/03 08:17:40 INFO Received uploads request method=POST path=/api/pending_closures1465--- PASS: TestTombstonedObjectOfferedWithoutWaiting (5.71s)1466=== CONT TestResolveDBConnectionString1467=== RUN TestResolveDBConnectionString/flag_wins1468=== PAUSE TestResolveDBConnectionString/flag_wins1469=== RUN TestResolveDBConnectionString/file_when_flag_empty1470=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1471=== RUN TestResolveDBConnectionString/missing_file_is_an_error1472=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1473=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1474=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1475=== RUN TestResolveDBConnectionString/nothing_configured1476=== PAUSE TestResolveDBConnectionString/nothing_configured1477=== CONT TestMetricsInventory1478--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (5.96s)1479=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock14802026/11/03 08:17:40 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=014812026/11/03 08:17:40 INFO Vacuumed table table=pending_closures14822026/11/03 08:17:40 INFO Vacuumed table table=pending_objects14832026/11/03 08:17:40 INFO Vacuumed table table=multipart_uploads14842026/11/03 08:17:40 INFO Vacuumed table table=closures14852026/11/03 08:17:40 INFO Vacuumed table table=objects14862026/11/03 08:17:40 INFO Aborted multipart uploads count=0 kept=014872026/11/03 08:17:40 WARN Force mode enabled - objects will be deleted immediately without grace period14882026/11/03 08:17:41 INFO Received uploads request method=POST path=/api/pending_closures14892026/11/03 08:17:41 INFO Aborted multipart uploads count=0 kept=014902026/11/03 08:17:41 WARN Force mode enabled - objects will be deleted immediately without grace period14912026/11/03 08:17:41 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014922026/11/03 08:17:41 INFO Vacuumed table table=pending_closures14932026/11/03 08:17:41 INFO Vacuumed table table=pending_objects14942026/11/03 08:17:41 INFO Vacuumed table table=multipart_uploads14952026/11/03 08:17:41 INFO Vacuumed table table=closures14962026/11/03 08:17:41 INFO Vacuumed table table=objects1497--- PASS: TestGCSweepSkipsPendingObjects (6.36s)1498=== CONT TestMetricsCommit14992026/11/03 08:17:41 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=01500=== RUN TestService_RequireScope_OIDC/builder_may_write1501=== PAUSE TestService_RequireScope_OIDC/builder_may_write1502=== RUN TestService_RequireScope_OIDC/builder_may_not_admin1503=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin1504=== RUN TestService_RequireScope_OIDC/ops_may_admin1505=== PAUSE TestService_RequireScope_OIDC/ops_may_admin1506=== RUN TestService_RequireScope_OIDC/ops_may_not_write1507=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write1508=== RUN TestService_RequireScope_OIDC/reader_may_not_write1509=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write1510=== RUN TestService_RequireScope_OIDC/static_token_may_admin1511=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin1512=== RUN TestService_RequireScope_OIDC/static_token_may_write1513=== PAUSE TestService_RequireScope_OIDC/static_token_may_write1514=== RUN TestService_RequireScope_OIDC/reader_may_read1515=== PAUSE TestService_RequireScope_OIDC/reader_may_read1516=== RUN TestService_RequireScope_OIDC/writer_implies_read1517=== PAUSE TestService_RequireScope_OIDC/writer_implies_read1518=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read1519=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read1520=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc1521=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc1522=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1523=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1524=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1525=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read1526=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1527=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1528=== CONT TestService_NativeMTLS15292026/11/03 08:17:41 INFO Vacuumed table table=pending_closures15302026/11/03 08:17:41 INFO Vacuumed table table=pending_objects15312026/11/03 08:17:41 INFO Vacuumed table table=multipart_uploads15322026/11/03 08:17:41 INFO Vacuumed table table=closures15332026/11/03 08:17:41 INFO Vacuumed table table=objects1534--- PASS: TestGCSweepDeliversEachKeyOnce (6.84s)1535=== CONT TestClientMultipleUploads15362026/11/03 08:17:41 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux15372026/11/03 08:17:41 WARN Refused reserved pin name=worker-x86_64-linux15382026/11/03 08:17:41 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux15392026/11/03 08:17:41 INFO Received create pin request method=POST path=/api/pins/my-app15402026/11/03 08:17:41 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1541--- PASS: TestCreatePin_ReservedPins (5.99s)1542=== CONT TestClientIntegration15432026/11/03 08:17:41 INFO Received uploads request method=POST path=/api/pending_closures1544--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.85s)1545=== CONT TestClientWithDependencies1546--- PASS: TestDeduplicatedObjectsRecordedAsPending (6.02s)1547=== CONT TestServerTLSConfig1548=== RUN TestServerTLSConfig/no_client_CA1549=== PAUSE TestServerTLSConfig/no_client_CA1550=== RUN TestServerTLSConfig/missing_CA_file1551=== PAUSE TestServerTLSConfig/missing_CA_file1552=== RUN TestServerTLSConfig/not_a_PEM_file1553=== PAUSE TestServerTLSConfig/not_a_PEM_file1554=== CONT TestMultipartCleanup15552026/11/03 08:17:42 INFO Received uploads request method=POST path=/api/pending_closures15562026/11/03 08:17:42 INFO Aborted multipart uploads count=0 kept=015572026/11/03 08:17:42 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=015582026/11/03 08:17:42 INFO Received create pin request method=POST path=/api/pins/myapp15592026/11/03 08:17:42 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=015602026/11/03 08:17:42 INFO Vacuumed table table=pending_closures15612026/11/03 08:17:42 INFO Created/updated pin name=myapp store_path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestPinProtectsFromGC2479957452/001/store/bwq5m2ilxx1m0qzcf6jjbvbjhfjdh2l7-pinned-file.txt narinfo_key=bwq5m2ilxx1m0qzcf6jjbvbjhfjdh2l7.narinfo15622026/11/03 08:17:42 INFO Vacuumed table table=pending_objects15632026/11/03 08:17:42 INFO Starting cleanup of old closures method=DELETE path=/api/closures15642026/11/03 08:17:42 INFO Garbage collection started15652026/11/03 08:17:42 INFO Vacuumed table table=multipart_uploads15662026/11/03 08:17:42 INFO Aborted multipart uploads count=0 kept=015672026/11/03 08:17:42 WARN Force mode enabled - objects will be deleted immediately without grace period15682026/11/03 08:17:42 INFO Vacuumed table table=closures15692026/11/03 08:17:42 INFO Vacuumed table table=objects15702026/11/03 08:17:42 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=015712026/11/03 08:17:42 INFO Vacuumed table table=pending_closures15722026/11/03 08:17:42 INFO Vacuumed table table=pending_objects15732026/11/03 08:17:42 INFO Aborted multipart uploads count=0 kept=015742026/11/03 08:17:42 INFO Vacuumed table table=multipart_uploads15752026/11/03 08:17:42 WARN Force mode enabled - objects will be deleted immediately without grace period15762026/11/03 08:17:42 INFO Vacuumed table table=closures15772026/11/03 08:17:42 INFO Vacuumed table table=objects15782026/11/03 08:17:42 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=015792026/11/03 08:17:42 INFO Vacuumed table table=pending_closures15802026/11/03 08:17:42 INFO Vacuumed table table=pending_objects15812026/11/03 08:17:42 INFO Vacuumed table table=multipart_uploads15822026/11/03 08:17:42 INFO Vacuumed table table=closures15832026/11/03 08:17:42 INFO Vacuumed table table=objects1584--- PASS: TestPushDedupSurvivesConcurrentGC (6.36s)1585=== CONT TestClientErrorHandling1586=== RUN TestClientErrorHandling/InvalidStorePath1587=== PAUSE TestClientErrorHandling/InvalidStorePath1588=== RUN TestClientErrorHandling/InvalidAuthToken1589=== PAUSE TestClientErrorHandling/InvalidAuthToken1590=== RUN TestClientErrorHandling/ServerNotAvailable1591=== PAUSE TestClientErrorHandling/ServerNotAvailable1592=== CONT TestService_ReadAuthMiddleware15932026/11/03 08:17:42 INFO Aborted multipart uploads count=0 kept=01594--- PASS: TestGCBugBareHashReferences (5.82s)1595=== CONT TestService_AuthMiddleware_OIDC15962026/11/03 08:17:42 WARN Force mode enabled - objects will be deleted immediately without grace period15972026/11/03 08:17:42 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=015982026/11/03 08:17:42 INFO Vacuumed table table=pending_closures15992026/11/03 08:17:42 INFO Vacuumed table table=pending_objects16002026/11/03 08:17:42 INFO Vacuumed table table=multipart_uploads16012026/11/03 08:17:42 INFO Vacuumed table table=closures16022026/11/03 08:17:42 INFO Vacuumed table table=objects1603--- PASS: TestGCMetrics (6.16s)1604=== CONT TestService_AuthMiddleware_MTLSBoundSubjects16052026/11/03 08:17:42 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51258/oidc16062026/11/03 08:17:42 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld4 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1607--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (5.68s)1608=== CONT TestNARDeduplicationMetadataUploadBug16092026/11/03 08:17:42 INFO lead: acquired remote=192.0.2.1:123416102026/11/03 08:17:43 INFO lead: acquired remote=192.0.2.1:123416112026/11/03 08:17:43 INFO lead: released remote=192.0.2.1:12341612--- PASS: TestLeadIncumbentAnnouncesAtOnce (5.06s)1613=== CONT TestCommitRacingPendingCleanupKeepsObjects1614--- PASS: TestCacheStatsHandler (5.16s)1615=== CONT TestGCTaskStore_StartNew1616--- PASS: TestGCTaskStore_StartNew (0.00s)1617=== CONT TestGCTaskStore_ConflictDifferentParams1618--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1619=== CONT TestGCEndsOnShutdown1620=== RUN TestGCEndsOnShutdown/before_the_run1621=== PAUSE TestGCEndsOnShutdown/before_the_run1622=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1623=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1624=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1625=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1626=== CONT TestGCTaskStore_DeduplicateSameParams1627--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1628=== CONT TestGCTaskStore_GetEmpty1629--- PASS: TestGCTaskStore_GetEmpty (0.00s)1630=== CONT TestPushWaitsForSweepHoldingRow16312026/11/03 08:17:43 INFO lead: acquired remote=192.0.2.1:12341632--- PASS: TestService_ReadScope_PublicByDefault (4.92s)1633=== CONT TestService_AuthMiddleware_MTLSProxyHeader1634--- PASS: TestObjectStatsUpdatedOncePerCommit (4.30s)1635=== CONT TestSweepRechecksPendingAfterLocking16362026/11/03 08:17:43 INFO lead: released remote=192.0.2.1:12341637--- PASS: TestLeadEndsOnShutdown (6.60s)1638=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1639=== NAME TestPinProtectsFromGC1640 client_integration_test.go:887: Pin successfully protected closure from garbage collection1641--- PASS: TestObjectStatsTrigger (4.67s)1642=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1643--- PASS: TestPinProtectsFromGC (11.13s)1644=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed16452026/11/03 08:17:44 INFO lead: released remote=192.0.2.1:123416462026/11/03 08:17:44 INFO lead: acquired remote=192.0.2.1:123416472026/11/03 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures16482026/11/03 08:17:44 INFO Received uploads request method=POST path=/api/pending_closures16492026/11/03 08:17:44 INFO Received cleanup request method=DELETE path=/api/pending_closures1650--- PASS: TestMetricsInventory (4.73s)1651=== CONT TestIsValidCachePath/narinfo1652=== CONT TestProxyWriteTimeout/narinfo1653=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed16542026/11/03 08:17:45 INFO lead: released remote=192.0.2.1:12341655--- PASS: TestLeadElectsOneAndHandsOver (7.16s)1656=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed16572026/11/03 08:17:45 WARN mTLS auth: subject not in bound subjects subject="CN=reader"16582026/11/03 08:17:45 WARN mTLS auth: subject not in bound subjects subject="CN=reader"1659--- PASS: TestService_NativeMTLS (4.54s)1660=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost1661=== NAME TestOrphanedObjectsGC1662 orphaned_objects_gc_test.go:287: GC Test Summary:1663 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1664 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1665 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1666 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1667 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1668=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed1669--- PASS: TestOrphanedObjectsGC (6.31s)1670--- PASS: TestConnectWaitsForAPeerMigration (6.79s)1671=== CONT TestPendingClosureWriteTimeout/empty1672=== CONT TestIsValidCachePath/ls1673=== CONT TestIsValidCachePath/short_hash1674=== CONT TestIsValidCachePath/wrong_extension1675=== CONT TestIsValidCachePath/leading_slash1676=== CONT TestIsValidCachePath/empty1677=== CONT TestIsValidCachePath/random_path1678=== CONT TestIsValidCachePath/invalid_char_u1679=== CONT TestIsValidCachePath/invalid_char_e1680=== CONT TestIsValidCachePath/traversal_in_middle1681=== CONT TestIsValidCachePath/traversal_parent1682=== CONT TestIsValidCachePath/index.html1683=== CONT TestIsValidCachePath/nix-cache-info1684=== CONT TestIsValidCachePath/realisation1685=== CONT TestIsValidCachePath/log1686=== CONT TestProxyWriteTimeout/unknown_size1687=== CONT TestIsValidCachePath/nar_uncompressed1688=== CONT TestIsValidCachePath/nar_bz21689=== CONT TestIsValidCachePath/nar_xz1690=== CONT TestIsValidCachePath/nar_zst1691=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1692=== CONT TestProxyWriteTimeout/1_GiB_nar1693=== CONT TestProxyWriteTimeout/10_GiB_nar1694=== CONT TestPendingClosureWriteTimeout/670k_objects1695=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline1696--- PASS: TestIsValidCachePath (0.10s)1697 --- PASS: TestIsValidCachePath/narinfo (0.00s)1698 --- PASS: TestIsValidCachePath/ls (0.00s)1699 --- PASS: TestIsValidCachePath/short_hash (0.00s)1700 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1701 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1702 --- PASS: TestIsValidCachePath/empty (0.00s)1703 --- PASS: TestIsValidCachePath/random_path (0.00s)1704 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1705 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1706 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1707 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1708 --- PASS: TestIsValidCachePath/index.html (0.00s)1709 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1710 --- PASS: TestIsValidCachePath/realisation (0.00s)1711 --- PASS: TestIsValidCachePath/log (0.00s)1712 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1713 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1714 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1715 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1716 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1717--- PASS: TestProxyWriteTimeout (0.00s)1718 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1719 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1720 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1721 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1722=== NAME TestClientMultipleUploads1723 client_integration_test.go:405: Created store path 0: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientMultipleUploads2012631427/001/store/70a3cchd2zppi8glij75kc0s7jxd1342-test-file-0.txt17242026/11/03 08:17:46 INFO Received push request method=POST path=/api/pushes17252026/11/03 08:17:46 INFO Received complete push request method=POST path=/api/pushes/1/complete1726 client_integration_test.go:405: Created store path 1: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientMultipleUploads2012631427/001/store/fw6dsnksr1ylz89v4pchx1bchrnk30nx-test-file-1.txt17272026/11/03 08:17:46 INFO Completed push id=1 objects=4 duration=20.7745ms17282026/11/03 08:17:46 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete17292026/11/03 08:17:46 INFO Completed upload id=2 objects=2 duration=537.5µs1730--- PASS: TestMetricsCommit (5.35s)1731=== CONT TestPendingClosureWriteTimeout/400_objects1732=== CONT TestParseSingleRange/none1733=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info17342026/11/03 08:17:46 INFO Received uploads request method=POST path=/1735=== CONT TestParseSingleRange/start_far_past_EOF1736=== CONT TestParseSingleRange/start_past_EOF1737=== CONT TestParseSingleRange/single_byte1738=== CONT TestParseSingleRange/suffix_exceeds_size1739=== CONT TestParseSingleRange/suffix1740=== CONT TestParseSingleRange/end_clamped_to_size1741=== CONT TestParseSingleRange/open-ended1742=== CONT TestParseSingleRange/closed1743=== CONT TestParseSingleRange/malformed_end_before_start1744=== CONT TestParseSingleRange/malformed_both_empty1745=== CONT TestParseSingleRange/malformed_no_dash1746=== CONT TestParseSingleRange/multi-range_ignored1747=== CONT TestParseSingleRange/unknown_unit1748--- PASS: TestParseSingleRange (0.12s)1749 --- PASS: TestParseSingleRange/none (0.00s)1750 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1751 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1752 --- PASS: TestParseSingleRange/single_byte (0.00s)1753 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1754 --- PASS: TestParseSingleRange/suffix (0.00s)1755 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1756 --- PASS: TestParseSingleRange/open-ended (0.00s)1757 --- PASS: TestParseSingleRange/closed (0.00s)1758 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1759 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1760 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1761 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1762 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1763=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key17642026/11/03 08:17:46 INFO Received complete multipart upload request method=POST path=/1765=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key17662026/11/03 08:17:46 INFO Received request for more parts method=POST path=/1767=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal17682026/11/03 08:17:46 INFO Received uploads request method=POST path=/1769--- PASS: TestUploadHandlersRejectInvalidKeys (0.11s)1770 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1771 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1772 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1773 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1774=== CONT TestIsValidUploadKey/narinfo1775=== CONT TestIsValidUploadKey/nix-cache-info1776=== CONT TestIsValidUploadKey/traversal1777=== CONT TestIsValidUploadKey/unknown_type1778=== CONT TestIsValidUploadKey/empty_key1779=== CONT TestIsValidUploadKey/absolute1780=== CONT TestIsValidUploadKey/traversal_nar1781=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1782=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1783=== CONT TestIsValidUploadKey/build_log_home-manager_file1784=== CONT TestIsValidUploadKey/realisation_plus_in_output1785=== CONT TestIsValidUploadKey/realisation1786=== CONT TestIsValidUploadKey/build_log_equals1787=== CONT TestIsValidUploadKey/build_log_question_mark1788=== CONT TestIsValidUploadKey/build_log_plus_in_name1789=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1790=== CONT TestIsValidUploadKey/index.html1791=== CONT TestIsValidUploadKey/nar_plain1792=== CONT TestIsValidUploadKey/build_log1793=== CONT TestIsValidUploadKey/listing1794=== CONT TestIsValidUploadKey/nar_xz1795=== CONT TestIsValidUploadKey/nar_zst1796--- PASS: TestIsValidUploadKey (0.11s)1797 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1798 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1799 --- PASS: TestIsValidUploadKey/traversal (0.00s)1800 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1801 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1802 --- PASS: TestIsValidUploadKey/absolute (0.00s)1803 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1804 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1805 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1806 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1807 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1808 --- PASS: TestIsValidUploadKey/realisation (0.00s)1809 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1810 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1811 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1812 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1813 --- PASS: TestIsValidUploadKey/index.html (0.00s)1814 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1815 --- PASS: TestIsValidUploadKey/build_log (0.00s)1816 --- PASS: TestIsValidUploadKey/listing (0.00s)1817 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1818 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1819=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure18202026/11/03 08:17:46 INFO Received uploads request method=POST path=/1821=== NAME TestClientMultipleUploads1822 client_integration_test.go:405: Created store path 2: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientMultipleUploads2012631427/001/store/gv8fg4vx52rkrapjn9hdc7g3c47i7gpm-test-file-2.txt1823--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (6.78s)1824=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts18252026/11/03 08:17:47 INFO Received request for more parts method=POST path=/1826=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart18272026/11/03 08:17:47 INFO Received complete multipart upload request method=POST path=/1828=== CONT TestPush_RejectsBadRequests/no_roots18292026/11/03 08:17:47 INFO Received push request method=POST path=/api/pushes1830=== CONT TestPush_RejectsBadRequests/root_not_in_objects18312026/11/03 08:17:47 INFO Received push request method=POST path=/api/pushes1832=== CONT TestPush_RejectsBadRequests/bad_root18332026/11/03 08:17:47 INFO Received push request method=POST path=/api/pushes1834=== CONT TestPush_RejectsBadRequests/no_objects18352026/11/03 08:17:47 INFO Received push request method=POST path=/api/pushes1836--- PASS: TestPush_RejectsBadRequests (6.61s)1837 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1838 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1839 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1840 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1841=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows18422026/11/03 08:17:47 INFO Received push request method=POST path=/api/pushes18432026/11/03 08:17:47 INFO Received uploads request method=POST path=/api/pending_closures18442026/11/03 08:17:47 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)18452026/11/03 08:17:47 INFO Uploading gv8fg4vx52rkrapjn9hdc7g3c47i7gpm-test-file-2.txt (160B)18462026/11/03 08:17:47 INFO Uploading fw6dsnksr1ylz89v4pchx1bchrnk30nx-test-file-1.txt (160B)18472026/11/03 08:17:47 INFO Uploading 70a3cchd2zppi8glij75kc0s7jxd1342-test-file-0.txt (160B)18482026/11/03 08:17:47 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"18492026/11/03 08:17:47 WARN Failed to register uploaded object key=gv8fg4vx52rkrapjn9hdc7g3c47i7gpm.ls error="server returned 404: 404 page not found\n"18502026/11/03 08:17:47 WARN Failed to register uploaded object key=70a3cchd2zppi8glij75kc0s7jxd1342.ls error="server returned 404: 404 page not found\n"18512026/11/03 08:17:47 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"18522026/11/03 08:17:47 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"18532026/11/03 08:17:47 WARN Failed to register uploaded object key=fw6dsnksr1ylz89v4pchx1bchrnk30nx.ls error="server returned 404: 404 page not found\n"1854=== NAME TestClientIntegration18552026/11/03 08:17:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1856 client_integration_test.go:291: Created store path: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientIntegration3333261270/002/store/h5kvqshy72mng0wmc7imp9qcwkrrgywv-test-file.txt18572026/11/03 08:17:47 INFO Signed narinfos id=1 count=318582026/11/03 08:17:47 INFO Uploading 3 narinfos18592026/11/03 08:17:47 WARN Failed to register uploaded object key=gv8fg4vx52rkrapjn9hdc7g3c47i7gpm.narinfo error="server returned 404: 404 page not found\n"18602026/11/03 08:17:47 INFO Received cleanup request method=DELETE path=/api/pending_closures18612026/11/03 08:17:47 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket81/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""18622026/11/03 08:17:47 INFO Aborted multipart uploads count=0 kept=118632026/11/03 08:17:47 WARN Failed to register uploaded object key=70a3cchd2zppi8glij75kc0s7jxd1342.narinfo error="server returned 404: 404 page not found\n"18642026/11/03 08:17:47 INFO Received complete push request method=POST path=/api/pushes/1/complete18652026/11/03 08:17:47 WARN Failed to register uploaded object key=fw6dsnksr1ylz89v4pchx1bchrnk30nx.narinfo error="server returned 404: 404 page not found\n"18662026/11/03 08:17:47 INFO Received cleanup request method=DELETE path=/api/pending_closures18672026/11/03 08:17:47 INFO Aborted multipart uploads count=1 kept=018682026/11/03 08:17:47 INFO Completed push id=1 objects=9 duration=15.084625ms18692026/11/03 08:17:47 INFO Upload complete. (334ms)1870=== NAME TestClientMultipleUploads1871 client_integration_test.go:416: Uploaded 3 paths in 699.218542ms1872--- PASS: TestMultipartCleanup (5.62s)1873=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18742026/11/03 08:17:47 INFO Received push request method=POST path=/api/pushes18752026/11/03 08:17:47 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18762026/11/03 08:17:47 INFO Uploading h5kvqshy72mng0wmc7imp9qcwkrrgywv-test-file.txt (152B)1877--- PASS: TestUploadHandlersRejectOversizedBody (0.20s)1878 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.05s)1879 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.03s)1880 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (0.88s)1881=== CONT TestCacheConfigHandler/full_config,_no_issuer1882=== CONT TestCacheConfigHandler/no_signing_keys1883--- PASS: TestClientMultipleUploads (6.19s)1884=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1885=== CONT TestCacheConfigHandler/no_cache_url_configured1886=== CONT TestResolveDBConnectionString/flag_wins1887=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1888=== CONT TestResolveDBConnectionString/missing_file_is_an_error1889=== CONT TestResolveDBConnectionString/nothing_configured1890=== CONT TestResolveDBConnectionString/file_when_flag_empty1891=== CONT TestService_RequireScope_OIDC/builder_may_write1892--- PASS: TestCacheConfigHandler (0.00s)1893 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)1894 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)1895 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)1896 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)18972026/11/03 08:17:47 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18982026/11/03 08:17:47 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign1899=== CONT TestService_RequireScope_OIDC/reader_may_read1900--- PASS: TestResolveDBConnectionString (0.01s)1901 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1902 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1903 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1904 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1905 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)19062026/11/03 08:17:47 WARN Failed to register uploaded object key=h5kvqshy72mng0wmc7imp9qcwkrrgywv.ls error="server returned 404: 404 page not found\n"1907=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read1908=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc1909=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc1910=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read19112026/11/03 08:17:47 INFO Signed narinfos id=1 count=119122026/11/03 08:17:47 WARN Authentication failed token_preview=wrong token_length=5 oidc_error="no provider could verify the token (signature or issuer mismatch)" oidc_provider="" tried_providers=[test]1913=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read1914=== CONT TestService_RequireScope_OIDC/writer_implies_read1915=== CONT TestService_RequireScope_OIDC/reader_may_not_write19162026/11/03 08:17:47 INFO Uploading 1 narinfos1917=== CONT TestService_RequireScope_OIDC/static_token_may_write1918=== CONT TestService_RequireScope_OIDC/ops_may_admin1919=== CONT TestService_RequireScope_OIDC/ops_may_not_write1920=== CONT TestService_RequireScope_OIDC/builder_may_not_admin1921=== CONT TestService_RequireScope_OIDC/static_token_may_admin1922=== CONT TestServerTLSConfig/no_client_CA1923=== CONT TestServerTLSConfig/missing_CA_file1924=== CONT TestClientErrorHandling/InvalidStorePath1925=== CONT TestServerTLSConfig/not_a_PEM_file1926--- PASS: TestServerTLSConfig (0.01s)1927 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)1928 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)1929 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.01s)1930=== CONT TestClientErrorHandling/ServerNotAvailable1931--- PASS: TestService_RequireScope_OIDC (6.08s)1932 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)1933 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)1934 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)1935 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)1936 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)1937 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.00s)1938 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)1939 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)1940 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)1941 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)1942 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)1943 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)1944 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)1945 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)19462026/11/03 08:17:47 INFO Received complete push request method=POST path=/api/pushes/1/complete19472026/11/03 08:17:47 WARN Failed to register uploaded object key=h5kvqshy72mng0wmc7imp9qcwkrrgywv.narinfo error="server returned 404: 404 page not found\n"19482026/11/03 08:17:47 INFO Completed push id=1 objects=3 duration=18.977208ms19492026/11/03 08:17:47 INFO Upload complete. (253ms)19502026/11/03 08:17:47 INFO All 1 paths already cached1951=== NAME TestClientIntegration1952 client_integration_test.go:317: Retrieved narinfo from S3:1953 StorePath: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientIntegration3333261270/002/store/h5kvqshy72mng0wmc7imp9qcwkrrgywv-test-file.txt1954 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1955 Compression: zstd1956 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11957 NarSize: 1521958 References: 1959 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11960 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1961 client_integration_test.go:318: Decompressed .ls content (64 bytes):1962 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}19632026/11/03 08:17:47 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/present1964--- PASS: TestService_ReadAuthMiddleware (5.36s)1965=== CONT TestClientErrorHandling/InvalidAuthToken19662026/11/03 08:17:47 WARN Request failed, retrying attempt=2 backoff=212.623049ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present19672026/11/03 08:17:48 INFO Received push request method=POST path=/api/pushes19682026/11/03 08:17:48 INFO Object in database but missing from S3 key=h5kvqshy72mng0wmc7imp9qcwkrrgywv.ls19692026/11/03 08:17:48 WARN Found objects in DB but missing from S3, will re-upload count=119702026/11/03 08:17:48 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19712026/11/03 08:17:48 INFO Received complete push request method=POST path=/api/pushes/2/complete19722026/11/03 08:17:48 WARN Failed to register uploaded object key=h5kvqshy72mng0wmc7imp9qcwkrrgywv.ls error="server returned 404: 404 page not found\n"19732026/11/03 08:17:48 INFO Completed push id=2 objects=3 duration=1.435667ms19742026/11/03 08:17:48 INFO Upload complete. (118ms)19752026/11/03 08:17:48 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"1976=== NAME TestClientWithDependencies1977 client_integration_test.go:660: Built derivation: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientWithDependencies3652468001/001/store/ikwcldj7in6900msankwnl5kby3l4hmp-test-script19782026/11/03 08:17:48 WARN mTLS auth: bound subjects configured but subject DN unavailable1979=== NAME TestClientIntegration19802026/11/03 08:17:48 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"1981 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1982--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (5.54s)1983=== CONT TestGCEndsOnShutdown/before_the_run1984=== NAME TestClientIntegration1985 client_integration_test.go:335: Decompressed .ls content (49 bytes):1986 {"version":1,"root":{"type":"regular","size":39}}19872026/11/03 08:17:48 WARN Request failed, retrying attempt=3 backoff=399.433358ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present1988=== NAME TestClientWithDependencies1989 client_integration_test.go:662: Found 1 dependencies (including self)19902026/11/03 08:17:48 INFO Received push request method=POST path=/api/pushes19912026/11/03 08:17:48 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19922026/11/03 08:17:48 INFO Uploading ikwcldj7in6900msankwnl5kby3l4hmp-test-script (136B)1993=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1994=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1995=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1996=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1997=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected19982026/11/03 08:17:48 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"1999=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected2000=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2001=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2002=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark20032026/11/03 08:17:48 WARN Failed to register uploaded object key=ikwcldj7in6900msankwnl5kby3l4hmp.ls error="server returned 404: 404 page not found\n"20042026/11/03 08:17:48 WARN Failed to register uploaded object key=log/4w98chbbx325zsjycm9m6mw5bi6cvrar-test-script.drv error="server returned 404: 404 page not found\n"20052026/11/03 08:17:48 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20062026/11/03 08:17:48 INFO Signed narinfos id=1 count=120072026/11/03 08:17:48 INFO Uploading 1 narinfos20082026/11/03 08:17:48 INFO Received push request method=POST path=/api/pushes20092026/11/03 08:17:48 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20102026/11/03 08:17:48 INFO Received complete push request method=POST path=/api/pushes/1/complete20112026/11/03 08:17:48 WARN Failed to register uploaded object key=ikwcldj7in6900msankwnl5kby3l4hmp.narinfo error="server returned 404: 404 page not found\n"20122026/11/03 08:17:48 INFO Received complete push request method=POST path=/api/pushes/3/complete20132026/11/03 08:17:48 WARN Failed to register uploaded object key=h5kvqshy72mng0wmc7imp9qcwkrrgywv.ls error="server returned 404: 404 page not found\n"20142026/11/03 08:17:48 INFO Completed push id=3 objects=3 duration=817.375µs20152026/11/03 08:17:48 INFO Upload complete. (112ms)2016=== NAME TestClientIntegration2017 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)2018 client_integration_test.go:352: Decompressed .ls content (49 bytes):2019 {"version":1,"root":{"type":"regular","size":39}}2020 client_integration_test.go:363: Testing garbage collection...20212026/11/03 08:17:48 INFO Completed push id=1 objects=4 duration=16.782375ms20222026/11/03 08:17:48 INFO Upload complete. (256ms)2023=== NAME TestClientWithDependencies2024 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestClientWithDependencies3652468001/001/store) requires matching store prefix20252026/11/03 08:17:48 INFO Starting cleanup of old closures method=DELETE path=/api/closures20262026/11/03 08:17:48 INFO Garbage collection started20272026/11/03 08:17:48 INFO Aborted multipart uploads count=0 kept=020282026/11/03 08:17:48 WARN Force mode enabled - objects will be deleted immediately without grace period20292026/11/03 08:17:48 WARN Request failed, retrying attempt=4 backoff=745.24219ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2030--- PASS: TestClientWithDependencies (6.72s)2031=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete20322026/11/03 08:17:48 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=1 objects-marked-for-deletion=3 objects-deleted-after-grace-period=3 objects-failed-to-delete=020332026/11/03 08:17:48 INFO Vacuumed table table=pending_closures2034=== NAME TestNARDeduplicationMetadataUploadBug2035 metadata_upload_test.go:48: First store path: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestNARDeduplicationMetadataUploadBug2601440835/001/store/0pgl7r7dv69dxbdfikkilrbybcfzd9wq-file1.txt20362026/11/03 08:17:49 INFO Vacuumed table table=pending_objects20372026/11/03 08:17:49 INFO Vacuumed table table=multipart_uploads20382026/11/03 08:17:49 INFO Vacuumed table table=closures20392026/11/03 08:17:49 INFO Vacuumed table table=objects20402026/11/03 08:17:49 INFO Received push request method=POST path=/api/pushes20412026/11/03 08:17:49 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20422026/11/03 08:17:49 INFO Uploading 0pgl7r7dv69dxbdfikkilrbybcfzd9wq-file1.txt (160B)20432026/11/03 08:17:49 INFO Aborted multipart uploads count=0 kept=020442026/11/03 08:17:49 WARN Failed to register uploaded object key=0pgl7r7dv69dxbdfikkilrbybcfzd9wq.ls error="server returned 404: 404 page not found\n"20452026/11/03 08:17:49 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20462026/11/03 08:17:49 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"20472026/11/03 08:17:49 INFO Signed narinfos id=1 count=120482026/11/03 08:17:49 WARN Force mode enabled - objects will be deleted immediately without grace period20492026/11/03 08:17:49 INFO Uploading 1 narinfos20502026/11/03 08:17:49 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=020512026/11/03 08:17:49 INFO Vacuumed table table=pending_closures20522026/11/03 08:17:49 INFO Vacuumed table table=pending_objects20532026/11/03 08:17:49 INFO Received complete push request method=POST path=/api/pushes/1/complete20542026/11/03 08:17:49 WARN Failed to register uploaded object key=0pgl7r7dv69dxbdfikkilrbybcfzd9wq.narinfo error="server returned 404: 404 page not found\n"20552026/11/03 08:17:49 INFO Vacuumed table table=multipart_uploads20562026/11/03 08:17:49 INFO Vacuumed table table=closures20572026/11/03 08:17:49 INFO Vacuumed table table=objects20582026/11/03 08:17:49 WARN Request failed, retrying attempt=5 backoff=1.692092181s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present20592026/11/03 08:17:49 INFO Completed push id=1 objects=3 duration=37.555291ms20602026/11/03 08:17:49 INFO Upload complete. (301ms)2061 metadata_upload_test.go:54: Retrieved narinfo from S3:2062 StorePath: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestNARDeduplicationMetadataUploadBug2601440835/001/store/0pgl7r7dv69dxbdfikkilrbybcfzd9wq-file1.txt2063 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2064 Compression: zstd2065 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2066 NarSize: 1602067 References: 2068 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2069--- PASS: TestCommitRacingPendingCleanupKeepsObjects (6.29s)2070=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2071=== NAME TestNARDeduplicationMetadataUploadBug2072 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)2073 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):2074 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}2075=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20762026/11/03 08:17:49 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]2077=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2078=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected20792026/11/03 08:17:49 WARN Authentication failed token_preview=eyJhbGciOi...UsRzTGCC2A token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]20802026/11/03 08:17:49 INFO Received uploads request method=POST path=/api/pending_closures2081--- PASS: TestService_AuthMiddleware_OIDC (5.87s)2082 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.01s)2083 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.00s)2084 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2085 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.00s)2086=== NAME TestNARDeduplicationMetadataUploadBug2087 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestNARDeduplicationMetadataUploadBug2601440835/001/store/k23vdjn9mwv76z23id3xzsa9fhv1905z-file2.txt20882026/11/03 08:17:49 INFO Received push request method=POST path=/api/pushes20892026/11/03 08:17:49 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)20902026/11/03 08:17:49 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign20912026/11/03 08:17:49 WARN Failed to register uploaded object key=k23vdjn9mwv76z23id3xzsa9fhv1905z.ls error="server returned 404: 404 page not found\n"20922026/11/03 08:17:49 INFO Signed narinfos id=2 count=120932026/11/03 08:17:49 INFO Uploading 1 narinfos2094--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.01s)20952026/11/03 08:17:49 INFO Received complete push request method=POST path=/api/pushes/2/complete20962026/11/03 08:17:49 WARN Failed to register uploaded object key=k23vdjn9mwv76z23id3xzsa9fhv1905z.narinfo error="server returned 404: 404 page not found\n"20972026/11/03 08:17:49 INFO Completed push id=2 objects=3 duration=852.583µs20982026/11/03 08:17:49 INFO Upload complete. (175ms)2099=== NAME TestNARDeduplicationMetadataUploadBug2100 metadata_upload_test.go:76: Retrieved narinfo from S3:2101 StorePath: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestNARDeduplicationMetadataUploadBug2601440835/001/store/k23vdjn9mwv76z23id3xzsa9fhv1905z-file2.txt2102 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst2103 Compression: zstd2104 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2105 NarSize: 1602106 References: 2107 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf2108 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)2109 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):2110 {"version":1,"root":{"type":"regular","size":44}}2111--- PASS: TestNARDeduplicationMetadataUploadBug (6.98s)2112--- PASS: TestPushWaitsForSweepHoldingRow (6.61s)21132026/11/03 08:17:50 INFO Aborted multipart uploads count=0 kept=021142026/11/03 08:17:50 WARN Force mode enabled - objects will be deleted immediately without grace period21152026/11/03 08:17:50 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=021162026/11/03 08:17:50 INFO Vacuumed table table=pending_closures21172026/11/03 08:17:50 INFO Vacuumed table table=pending_objects21182026/11/03 08:17:50 INFO Vacuumed table table=multipart_uploads21192026/11/03 08:17:50 INFO Vacuumed table table=closures21202026/11/03 08:17:50 INFO Vacuumed table table=objects2121--- PASS: TestSweepRechecksPendingAfterLocking (6.29s)21222026/11/03 08:17:50 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02123=== NAME TestClientIntegration2124 client_integration_test.go:370: Objects in database after GC:2125 client_integration_test.go:370: Successfully deleted all objects with GC --force21262026/11/03 08:17:50 INFO Received uploads request method=POST path=/api/pending_closures2127--- PASS: TestClientIntegration (8.98s)21282026/11/03 08:17:50 INFO Aborted multipart uploads count=1 kept=021292026/11/03 08:17:50 INFO Received cleanup request method=DELETE path=/api/pending_closures21302026/11/03 08:17:50 INFO Aborted multipart uploads count=1 kept=02131--- PASS: TestPendingCleanupUsesOneCutoff (10.99s)21322026/11/03 08:17:51 INFO Received uploads request method=POST path=/api/pending_closures21332026/11/03 08:17:51 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/03 08:17:51 WARN Request failed, retrying attempt=2 backoff=212.616015ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2135--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.02s)2136 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (6.83s)2137 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (6.85s)21382026/11/03 08:17:51 INFO Received uploads request method=POST path=/api/pending_closures21392026/11/03 08:17:51 WARN Request failed, retrying attempt=3 backoff=361.7091ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21402026/11/03 08:17:51 INFO Received uploads request method=POST path=/api/pending_closures21412026/11/03 08:17:51 WARN Request failed, retrying attempt=4 backoff=745.26812ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21422026/11/03 08:17:52 INFO Received uploads request method=POST path=/api/pending_closures21432026/11/03 08:17:52 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21442026/11/03 08:17:52 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjA5OWEzZjU2LWQ0MDgtNDExYy1iM2EzLWZiYzQ5ZjE5NmZhYXgxNzkzNjkzODcwNjIwMTcyMDAw parts=1021452026/11/03 08:17:52 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21462026/11/03 08:17:52 INFO Completed upload id=1 objects=3 duration=24.605291ms21472026/11/03 08:17:52 WARN Request failed, retrying attempt=5 backoff=1.637051742s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21482026/11/03 08:17:52 INFO Received uploads request method=POST path=/api/pending_closures21492026/11/03 08:17:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21502026/11/03 08:17:53 INFO Received uploads request method=POST path=/api/pending_closures21512026/11/03 08:17:53 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21522026/11/03 08:17:53 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21532026/11/03 08:17:53 INFO Received uploads request method=POST path=/api/pending_closures21542026/11/03 08:17:53 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjA5Zjk1NjIzLWRlNDYtNDdiMC05YTg5LTEyMjExZjJiMjRlZXgxNzkzNjkzODcxMTUxNDAyMDAw parts=1021552026/11/03 08:17:53 INFO Aborted multipart uploads count=0 kept=021562026/11/03 08:17:53 WARN Force mode enabled - objects will be deleted immediately without grace period21572026/11/03 08:17:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21582026/11/03 08:17:53 INFO Completed upload id=1 objects=3 duration=16.129625ms21592026/11/03 08:17:53 INFO Received uploads request method=POST path=/api/pending_closures2160--- PASS: TestPendingClosureWriteTimeout (0.00s)2161 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2162 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2163 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2164 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (7.32s)21652026/11/03 08:17:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21662026/11/03 08:17:53 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=021672026/11/03 08:17:53 INFO Vacuumed table table=pending_closures21682026/11/03 08:17:53 INFO Vacuumed table table=pending_objects21692026/11/03 08:17:53 INFO Vacuumed table table=multipart_uploads21702026/11/03 08:17:53 INFO Vacuumed table table=closures21712026/11/03 08:17:53 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLmM1NTI1NWFkLWUxOWYtNDgzNy1hZWU3LWRmNzMyNzgzNzI1NngxNzkzNjkzODcxNDY5MjIyMDAw parts=1021722026/11/03 08:17:53 INFO Vacuumed table table=objects21732026/11/03 08:17:53 INFO Received uploads request method=POST path=/api/pending_closures21742026/11/03 08:17:53 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21752026/11/03 08:17:53 INFO Completed upload id=1 objects=3 duration=16.980375ms21762026/11/03 08:17:53 INFO Received uploads request method=POST path=/api/pending_closures21772026/11/03 08:17:53 INFO Aborted multipart uploads count=0 kept=021782026/11/03 08:17:53 WARN Force mode enabled - objects will be deleted immediately without grace period21792026/11/03 08:17:53 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=021802026/11/03 08:17:53 INFO Vacuumed table table=pending_closures21812026/11/03 08:17:53 INFO Vacuumed table table=pending_objects21822026/11/03 08:17:53 INFO Vacuumed table table=multipart_uploads21832026/11/03 08:17:53 INFO Vacuumed table table=closures21842026/11/03 08:17:53 INFO Vacuumed table table=objects2185--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2186 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (6.52s)2187 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (6.32s)21882026/11/03 08:17:53 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21892026/11/03 08:17:53 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjViNjk1MjA5LWU3NzQtNDBmNS1hMmEzLTM0NGUwNzJlMmZjY3gxNzkzNjkzODcxNzg0MzQyMDAw parts=1021902026/11/03 08:17:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21912026/11/03 08:17:54 INFO Completed upload id=1 objects=3 duration=9.015125ms21922026/11/03 08:17:54 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"21932026/11/03 08:17:54 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-config21942026/11/03 08:17:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21952026/11/03 08:17:54 WARN Request failed, retrying attempt=2 backoff=186.026196ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21962026/11/03 08:17:54 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjU1ZjUyMWM1LWYyODEtNGM3MC04NzQwLWUzMDQ4ZWZkODQ1ZHgxNzkzNjkzODcyMjA2NzgyMDAw parts=1021972026/11/03 08:17:54 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21982026/11/03 08:17:54 INFO Completed upload id=1 objects=3 duration=9.1695ms21992026/11/03 08:17:54 INFO Received uploads request method=POST path=/api/pending_closures22002026/11/03 08:17:54 INFO Received uploads request method=POST path=/api/pending_closures22012026/11/03 08:17:54 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22022026/11/03 08:17:54 WARN Found objects in DB but missing from S3, will re-upload count=122032026/11/03 08:17:54 WARN Request failed, retrying attempt=3 backoff=408.770083ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22042026/11/03 08:17:54 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22052026/11/03 08:17:54 INFO Aborted multipart uploads count=0 kept=022062026/11/03 08:17:54 WARN Force mode enabled - objects will be deleted immediately without grace period22072026-11-03 08:17:54.775 UTC [28938] ERROR: canceling statement due to user request22082026-11-03 08:17:54.775 UTC [28938] STATEMENT: -- name: MarkStaleObjects :execrows2209 WITH RECURSIVE ct AS (2210 SELECT timezone('UTC', now()) AS now2211 ),2212 closure_reach AS (2213 -- Start with all closure keys2214 SELECT o.key, o.refs2215 FROM objects o2216 INNER JOIN closures c ON o.key = c.key2217 UNION2218 -- Recursively add all referenced objects2219 SELECT o.key, o.refs2220 FROM objects o2221 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2222 ),2223 reachable_objects AS (2224 SELECT DISTINCT key FROM closure_reach2225 ),2226 stale_objects AS (2227 SELECT o.key2228 FROM objects AS o, ct2229 WHERE2230 NOT EXISTS (2231 SELECT 12232 FROM reachable_objects ro2233 WHERE ro.key = o.key2234 )2235 AND NOT EXISTS (2236 SELECT 12237 FROM pending_objects AS po2238 WHERE po.key = o.key2239 )2240 AND o.deleted_at IS NULL -- Only mark fresh objects2241 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2242 FOR UPDATE2243 )2244 UPDATE objects2245 SET2246 deleted_at = ct.now,2247 first_deleted_at = COALESCE(first_deleted_at, ct.now)2248 FROM stale_objects, ct2249 WHERE objects.key = stale_objects.key2250 22512026/11/03 08:17:54 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22522026/11/03 08:17:54 WARN Request failed, retrying attempt=4 backoff=809.063341ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22532026/11/03 08:17:54 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22542026/11/03 08:17:55 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjQ1N2ZhYWEzLWMzYWEtNDlhNC1hYzdjLWY3NjMxZjEyZWRhZngxNzkzNjkzODczMjg0MTE0MDAw parts=1022552026/11/03 08:17:55 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22562026/11/03 08:17:55 INFO Completed upload id=2 objects=3 duration=774.25µs22572026/11/03 08:17:55 INFO Aborted multipart uploads count=0 kept=022582026/11/03 08:17:55 WARN Force mode enabled - objects will be deleted immediately without grace period22592026/11/03 08:17:55 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:50917/bucket105/?delete=\": context canceled"2260--- PASS: TestGCEndsOnShutdown (0.00s)2261 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (6.36s)2262 --- PASS: TestGCEndsOnShutdown/before_the_run (6.87s)2263 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (6.71s)22642026/11/03 08:17:55 INFO Received uploads request method=POST path=/api/pending_closures22652026/11/03 08:17:55 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22662026/11/03 08:17:55 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo22672026/11/03 08:17:55 WARN Request failed, retrying attempt=5 backoff=1.703552964s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22682026/11/03 08:17:55 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22692026/11/03 08:17:55 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=NTliNGJjOWMtNWFmNC00MTFlLWEzNmYtYzA2OGFmN2VlZDhhLjcyODIzMDVjLTlkMzItNGViMC1hM2Y1LTM3YzM4ZDBkOWI1OXgxNzkzNjkzODc0NDQyNjM2MDAw parts=1022702026/11/03 08:17:55 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22712026/11/03 08:17:55 INFO Completed upload id=2 objects=3 duration=1.23775ms2272=== NAME TestOrphanedObjectsGCStressTest2273 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2274 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion22752026/11/03 08:17:56 INFO Received uploads request method=POST path=/api/pending_closures22762026/11/03 08:17:56 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22772026/11/03 08:17:56 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2278--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.09s)2279 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (8.62s)2280 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (7.70s)2281 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (9.44s)2282 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (9.61s)2283 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (10.14s)22842026/11/03 08:17:57 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_closures22852026/11/03 08:17:57 WARN Request failed, retrying attempt=2 backoff=207.314905ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22862026/11/03 08:17:57 WARN Request failed, retrying attempt=3 backoff=395.424057ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22872026/11/03 08:17:58 WARN Request failed, retrying attempt=4 backoff=783.371875ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22882026/11/03 08:17:58 WARN Request failed, retrying attempt=5 backoff=1.72981157s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2289--- PASS: TestClientErrorHandling (0.01s)2290 --- PASS: TestClientErrorHandling/InvalidStorePath (6.36s)2291 --- PASS: TestClientErrorHandling/InvalidAuthToken (6.96s)2292 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.19s)2293=== NAME TestOrphanedObjectsGCStressTest2294 orphaned_objects_gc_test.go:503: Stress test completed successfully:2295 orphaned_objects_gc_test.go:504: - Active objects preserved: 202296 orphaned_objects_gc_test.go:505: - Objects deleted: 2102297 orphaned_objects_gc_test.go:506: - Total GC'd: 2102298--- PASS: TestOrphanedObjectsGCStressTest (25.14s)2299PASS2300{"timestamp":"2026-11-03T08:18:04.88999Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51461","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(5)"}2301{"timestamp":"2026-11-03T08:18:04.891241Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51063","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(10)"}2302{"timestamp":"2026-11-03T08:18:04.891728Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51441","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(3)"}2303{"timestamp":"2026-11-03T08:18:04.892067Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:51339","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(3)"}23042026-11-03 08:18:05.019 UTC [28455] LOG: received smart shutdown request23052026-11-03 08:18:05.021 UTC [28455] LOG: background worker "logical replication launcher" (PID 28465) exited with exit code 123062026-11-03 08:18:05.044 UTC [28460] LOG: shutting down23072026-11-03 08:18:05.046 UTC [28460] LOG: checkpoint starting: shutdown immediate23082026-11-03 08:18:06.747 UTC [28460] LOG: checkpoint complete: wrote 12045 buffers (73.5%), wrote 4 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.931 s, sync=0.706 s, total=1.703 s; sync files=35724, longest=0.001 s, average=0.001 s; distance=525323 kB, estimate=525323 kB; lsn=0/2188FC20, redo lsn=0/2188FC2023092026-11-03 08:18:06.757 UTC [28455] LOG: database system is shut down2310Running OIDC tests...2311=== RUN TestAudienceForIssuer2312=== PAUSE TestAudienceForIssuer2313=== RUN TestGlobMatch2314=== PAUSE TestGlobMatch2315=== RUN TestValidateToken_ValidToken2316=== PAUSE TestValidateToken_ValidToken2317=== RUN TestValidateToken_WrongAudience2318=== PAUSE TestValidateToken_WrongAudience2319=== RUN TestValidateToken_Expired2320=== PAUSE TestValidateToken_Expired2321=== RUN TestValidateToken_BoundClaimsMismatch2322=== PAUSE TestValidateToken_BoundClaimsMismatch2323=== RUN TestValidateToken_BoundSubjectMismatch2324=== PAUSE TestValidateToken_BoundSubjectMismatch2325=== RUN TestValidateToken_MultipleProviders2326=== PAUSE TestValidateToken_MultipleProviders2327=== RUN TestValidateToken_NoMatchingProvider2328=== PAUSE TestValidateToken_NoMatchingProvider2329=== RUN TestValidateToken_KubernetesServiceAccount2330=== PAUSE TestValidateToken_KubernetesServiceAccount2331=== RUN TestNewValidator_KubernetesRequiresCA2332=== PAUSE TestNewValidator_KubernetesRequiresCA2333=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2334=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2335=== RUN TestPins_ReservedForMatchingRule2336=== PAUSE TestPins_ReservedForMatchingRule2337=== RUN TestPins_TopLevelShorthand2338=== PAUSE TestPins_TopLevelShorthand2339=== RUN TestPins_ConfigValidation2340=== PAUSE TestPins_ConfigValidation2341=== RUN TestScopes_LegacyProviderDefaultsToWrite2342=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2343=== RUN TestScopes_Rules2344=== PAUSE TestScopes_Rules2345=== RUN TestScopes_ConfigValidation2346=== PAUSE TestScopes_ConfigValidation2347=== CONT TestAudienceForIssuer2348--- PASS: TestAudienceForIssuer (0.00s)2349=== CONT TestValidateToken_Expired2350=== CONT TestValidateToken_BoundClaimsMismatch2351=== CONT TestValidateToken_MultipleProviders2352=== CONT TestValidateToken_KubernetesServiceAccount2353=== CONT TestScopes_ConfigValidation2354=== CONT TestScopes_Rules2355--- PASS: TestScopes_ConfigValidation (0.00s)2356=== CONT TestScopes_LegacyProviderDefaultsToWrite2357=== CONT TestPins_ConfigValidation2358--- PASS: TestPins_ConfigValidation (0.00s)2359=== CONT TestPins_TopLevelShorthand2360=== CONT TestPins_ReservedForMatchingRule2361=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2362=== CONT TestNewValidator_KubernetesRequiresCA2363=== CONT TestValidateToken_NoMatchingProvider2364=== CONT TestValidateToken_BoundSubjectMismatch2365=== CONT TestValidateToken_ValidToken2366=== CONT TestValidateToken_WrongAudience2367=== CONT TestGlobMatch2368=== RUN TestGlobMatch/foo_foo2369=== PAUSE TestGlobMatch/foo_foo2370=== RUN TestGlobMatch/foo_bar2371=== PAUSE TestGlobMatch/foo_bar2372=== RUN TestGlobMatch/*_2373=== PAUSE TestGlobMatch/*_2374=== RUN TestGlobMatch/*_anything2375=== PAUSE TestGlobMatch/*_anything2376=== RUN TestGlobMatch/foo*_foo2377=== PAUSE TestGlobMatch/foo*_foo2378=== RUN TestGlobMatch/foo*_foobar2379=== PAUSE TestGlobMatch/foo*_foobar2380=== RUN TestGlobMatch/foo*_bar2381=== PAUSE TestGlobMatch/foo*_bar2382=== RUN TestGlobMatch/*bar_bar2383=== PAUSE TestGlobMatch/*bar_bar2384=== RUN TestGlobMatch/*bar_foobar2385=== PAUSE TestGlobMatch/*bar_foobar2386=== RUN TestGlobMatch/*bar_foo2387=== PAUSE TestGlobMatch/*bar_foo2388=== RUN TestGlobMatch/foo*bar_foobar2389=== PAUSE TestGlobMatch/foo*bar_foobar2390=== RUN TestGlobMatch/foo*bar_foo123bar2391=== PAUSE TestGlobMatch/foo*bar_foo123bar2392=== RUN TestGlobMatch/foo*bar_foobarbaz2393=== PAUSE TestGlobMatch/foo*bar_foobarbaz2394=== RUN TestGlobMatch/*/*_foo/bar2395=== PAUSE TestGlobMatch/*/*_foo/bar2396=== RUN TestGlobMatch/*/*_foo2397=== PAUSE TestGlobMatch/*/*_foo2398=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2399=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2400=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02401=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02402=== RUN TestGlobMatch/refs/*/main_refs/heads/main2403=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2404=== RUN TestGlobMatch/fo?_foo2405=== PAUSE TestGlobMatch/fo?_foo2406=== RUN TestGlobMatch/fo?_fo2407=== PAUSE TestGlobMatch/fo?_fo2408=== RUN TestGlobMatch/fo?_fooo2409=== PAUSE TestGlobMatch/fo?_fooo2410=== RUN TestGlobMatch/?oo_foo2411=== PAUSE TestGlobMatch/?oo_foo2412=== RUN TestGlobMatch/?oo_boo2413=== PAUSE TestGlobMatch/?oo_boo2414=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2415=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2416=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2417=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2418=== CONT TestGlobMatch/foo_foo2419=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2420=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2421=== CONT TestGlobMatch/?oo_boo2422=== CONT TestGlobMatch/?oo_foo2423=== CONT TestGlobMatch/fo?_fooo2424=== CONT TestGlobMatch/fo?_fo2425=== CONT TestGlobMatch/fo?_foo2426=== CONT TestGlobMatch/refs/*/main_refs/heads/main2427=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02428=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2429=== CONT TestGlobMatch/*/*_foo2430=== CONT TestGlobMatch/*/*_foo/bar2431=== CONT TestGlobMatch/foo*bar_foobarbaz2432=== CONT TestGlobMatch/foo*bar_foo123bar2433=== CONT TestGlobMatch/foo*bar_foobar2434=== CONT TestGlobMatch/*bar_foo2435=== CONT TestGlobMatch/*bar_foobar2436=== CONT TestGlobMatch/*bar_bar2437=== CONT TestGlobMatch/foo*_bar2438=== CONT TestGlobMatch/foo*_foobar2439=== CONT TestGlobMatch/foo*_foo2440=== CONT TestGlobMatch/*_anything2441=== CONT TestGlobMatch/*_2442=== CONT TestGlobMatch/foo_bar2443--- PASS: TestGlobMatch (0.01s)2444 --- PASS: TestGlobMatch/foo_foo (0.00s)2445 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2446 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2447 --- PASS: TestGlobMatch/?oo_boo (0.00s)2448 --- PASS: TestGlobMatch/?oo_foo (0.00s)2449 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2450 --- PASS: TestGlobMatch/fo?_fo (0.00s)2451 --- PASS: TestGlobMatch/fo?_foo (0.00s)2452 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2453 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2454 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2455 --- PASS: TestGlobMatch/*/*_foo (0.00s)2456 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2457 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2458 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2459 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2460 --- PASS: TestGlobMatch/*bar_foo (0.00s)2461 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2462 --- PASS: TestGlobMatch/*bar_bar (0.00s)2463 --- PASS: TestGlobMatch/foo*_bar (0.00s)2464 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2465 --- PASS: TestGlobMatch/foo*_foo (0.00s)2466 --- PASS: TestGlobMatch/*_anything (0.00s)2467 --- PASS: TestGlobMatch/*_ (0.00s)2468 --- PASS: TestGlobMatch/foo_bar (0.00s)24692026/11/03 08:18:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51503/oidc24702026/11/03 08:18:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51501/oidc24712026/11/03 08:18:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51500/oidc24722026/11/03 08:18:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51506/oidc2473--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.09s)2474--- PASS: TestPins_ReservedForMatchingRule (0.08s)2475--- PASS: TestValidateToken_BoundClaimsMismatch (0.09s)24762026/11/03 08:18:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51508/oidc2477--- PASS: TestScopes_Rules (0.10s)2478--- PASS: TestValidateToken_WrongAudience (0.06s)24792026/11/03 08:18:08 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:51498/oidc24802026/11/03 08:18:08 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:51510/oidc2481--- PASS: TestValidateToken_MultipleProviders (0.12s)24822026/11/03 08:18:08 http: TLS handshake error from 127.0.0.1:51512: read tcp 127.0.0.1:51511->127.0.0.1:51512: use of closed network connection2483--- PASS: TestNewValidator_KubernetesRequiresCA (0.11s)24842026/11/03 08:18:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51515/oidc2485--- PASS: TestValidateToken_ValidToken (0.11s)24862026/11/03 08:18:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51517/oidc2487--- PASS: TestValidateToken_BoundSubjectMismatch (0.15s)24882026/11/03 08:18:08 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:51499/oidc2489--- PASS: TestValidateToken_NoMatchingProvider (0.17s)24902026/11/03 08:18:08 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:515212491--- PASS: TestValidateToken_KubernetesServiceAccount (0.19s)24922026/11/03 08:18:08 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC12324932026/11/03 08:18:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51525/oidc2494--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.18s)2495--- PASS: TestValidateToken_Expired (0.20s)24962026/11/03 08:18:08 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:51528/oidc2497--- PASS: TestPins_TopLevelShorthand (0.22s)2498PASS2499Running hook tests...2500=== RUN TestSendPathsEmpty2501=== PAUSE TestSendPathsEmpty2502=== RUN TestQueueEnqueueAndFetch2503=== PAUSE TestQueueEnqueueAndFetch2504=== RUN TestQueueDeduplication2505=== PAUSE TestQueueDeduplication2506=== RUN TestQueueRemove2507=== PAUSE TestQueueRemove2508=== RUN TestQueueFetchBatchLimit2509=== PAUSE TestQueueFetchBatchLimit2510=== RUN TestQueueRetryMovesToBack2511=== PAUSE TestQueueRetryMovesToBack2512=== RUN TestQueueFetchRemoveLifecycle2513=== PAUSE TestQueueFetchRemoveLifecycle2514=== RUN TestQueueConcurrentWriters2515=== PAUSE TestQueueConcurrentWriters2516=== RUN TestQueueRemoveLargeClosure2517=== PAUSE TestQueueRemoveLargeClosure2518=== RUN TestServerClientIntegration2519--- PASS: TestServerClientIntegration (0.00s)2520=== RUN TestServerQueueError25212026/11/03 08:18:09 ERROR Failed to queue paths error="permission denied" count=12522--- PASS: TestServerQueueError (0.00s)2523=== RUN TestGetListenerSocketActivation2524 server_test.go:145: systemd socket activation does not exist on darwin2525--- SKIP: TestGetListenerSocketActivation (0.00s)2526=== RUN TestServerStalledClientDoesNotBlockShutdown2527=== PAUSE TestServerStalledClientDoesNotBlockShutdown2528=== RUN TestServerBacksOffOnAcceptErrors2529=== PAUSE TestServerBacksOffOnAcceptErrors2530=== RUN TestDrainIsolatesPoisonPath2531=== PAUSE TestDrainIsolatesPoisonPath2532=== RUN TestRunNotBlockedByPoisonHead2533=== PAUSE TestRunNotBlockedByPoisonHead2534=== RUN TestDrainGivesUpWhenServerDown2535=== PAUSE TestDrainGivesUpWhenServerDown2536=== RUN TestFailedPathPrunedByLaterClosure2537=== PAUSE TestFailedPathPrunedByLaterClosure2538=== RUN TestWorkerUploadsAndRemoves2539=== PAUSE TestWorkerUploadsAndRemoves2540=== RUN TestWorkerSkipsGCdPaths2541=== PAUSE TestWorkerSkipsGCdPaths2542=== RUN TestWorkerPrunesClosureDeps2543=== PAUSE TestWorkerPrunesClosureDeps2544=== RUN TestDrainTimeout2545=== PAUSE TestDrainTimeout2546=== RUN TestWorkerRemoveFailureIsNotProgress2547=== PAUSE TestWorkerRemoveFailureIsNotProgress2548=== RUN TestWorkerKeepsPathItCannotStat2549=== PAUSE TestWorkerKeepsPathItCannotStat2550=== CONT TestSendPathsEmpty2551--- PASS: TestSendPathsEmpty (0.00s)2552=== CONT TestWorkerKeepsPathItCannotStat2553=== CONT TestServerBacksOffOnAcceptErrors2554=== CONT TestQueueFetchRemoveLifecycle25552026/11/03 08:18:09 ERROR Accept failed error="too many open files"2556=== CONT TestQueueRemove2557=== CONT TestServerStalledClientDoesNotBlockShutdown2558=== CONT TestQueueRemoveLargeClosure2559=== CONT TestQueueConcurrentWriters2560=== CONT TestQueueFetchBatchLimit2561=== CONT TestWorkerUploadsAndRemoves2562=== CONT TestWorkerRemoveFailureIsNotProgress2563=== CONT TestDrainTimeout2564=== CONT TestWorkerPrunesClosureDeps2565=== CONT TestWorkerSkipsGCdPaths2566=== CONT TestQueueDeduplication2567=== CONT TestQueueEnqueueAndFetch2568=== CONT TestDrainGivesUpWhenServerDown2569=== CONT TestFailedPathPrunedByLaterClosure2570=== CONT TestRunNotBlockedByPoisonHead2571=== CONT TestDrainIsolatesPoisonPath2572=== CONT TestQueueRetryMovesToBack25732026/11/03 08:18:09 ERROR Accept failed error="too many open files"25742026/11/03 08:18:09 INFO Upload queue status pending=225752026/11/03 08:18:09 INFO Uploading batch count=22576--- PASS: TestQueueEnqueueAndFetch (0.01s)25772026/11/03 08:18:09 INFO Upload queue status pending=225782026/11/03 08:18:09 INFO Uploading batch count=125792026/11/03 08:18:09 INFO Upload queue status pending=225802026/11/03 08:18:09 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestWorkerSkipsGCdPaths4262714498/002/nonexistent25812026/11/03 08:18:09 INFO Uploading batch count=12582--- PASS: TestQueueFetchBatchLimit (0.01s)25832026/11/03 08:18:09 INFO Uploading batch count=225842026/11/03 08:18:09 INFO Uploading batch count=125852026/11/03 08:18:09 ERROR Upload failed error="upload failed" count=125862026/11/03 08:18:09 INFO Uploading batch count=425872026/11/03 08:18:09 ERROR Upload failed error="upload failed" count=425882026/11/03 08:18:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestDrainIsolatesPoisonPath3600466055/002/bbb25892026/11/03 08:18:09 INFO Uploading batch count=125902026/11/03 08:18:09 INFO Upload queue status pending=325912026/11/03 08:18:09 INFO Uploading batch count=125922026/11/03 08:18:09 ERROR Upload failed error="upload failed" count=125932026/11/03 08:18:09 INFO Uploading batch count=125942026/11/03 08:18:09 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestWorkerKeepsPathItCannotStat2199294789/002/locked/aaa error="stat /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestWorkerKeepsPathItCannotStat2199294789/002/locked/aaa: permission denied"25952026/11/03 08:18:09 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestWorkerKeepsPathItCannotStat2199294789/002/locked/aaa error="stat /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestWorkerKeepsPathItCannotStat2199294789/002/locked/aaa: permission denied"25962026/11/03 08:18:09 WARN Cannot stat store path, will retry later path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestWorkerKeepsPathItCannotStat2199294789/002/locked/aaa error="stat /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestWorkerKeepsPathItCannotStat2199294789/002/locked/aaa: permission denied"25972026/11/03 08:18:09 INFO Uploading batch count=125982026/11/03 08:18:09 ERROR Upload failed error="upload failed" count=125992026/11/03 08:18:09 ERROR Drain finished with paths left in queue remaining=12600--- PASS: TestQueueFetchRemoveLifecycle (0.01s)2601--- PASS: TestQueueRetryMovesToBack (0.01s)26022026/11/03 08:18:09 INFO Uploading batch count=226032026/11/03 08:18:09 ERROR Upload failed error="upload failed" count=226042026/11/03 08:18:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestDrainGivesUpWhenServerDown1563316562/002/a26052026/11/03 08:18:09 INFO Uploading batch count=126062026/11/03 08:18:09 ERROR Upload failed error="upload failed" count=12607--- PASS: TestQueueRemove (0.02s)26082026/11/03 08:18:09 INFO Uploading batch count=126092026/11/03 08:18:09 ERROR Upload failed error="upload failed" count=126102026/11/03 08:18:09 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestWorkerRemoveFailureIsNotProgress3937359662/002/nonexistent26112026/11/03 08:18:09 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126122026/11/03 08:18:09 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestWorkerRemoveFailureIsNotProgress3937359662/002/nonexistent26132026/11/03 08:18:09 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126142026/11/03 08:18:09 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestWorkerRemoveFailureIsNotProgress3937359662/002/nonexistent26152026/11/03 08:18:09 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126162026/11/03 08:18:09 ERROR Drain finished with paths left in queue remaining=126172026/11/03 08:18:09 ERROR Drain finished with paths left in queue remaining=126182026/11/03 08:18:09 ERROR Accept failed error="too many open files"2619--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)2620--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)2621--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)26222026/11/03 08:18:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestDrainGivesUpWhenServerDown1563316562/002/b2623--- PASS: TestQueueDeduplication (0.01s)26242026/11/03 08:18:09 INFO Uploading batch count=226252026/11/03 08:18:09 ERROR Upload failed error="upload failed" count=226262026/11/03 08:18:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestDrainGivesUpWhenServerDown1563316562/002/c26272026/11/03 08:18:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestDrainGivesUpWhenServerDown1563316562/002/d26282026/11/03 08:18:09 INFO Uploading batch count=226292026/11/03 08:18:09 ERROR Upload failed error="upload failed" count=226302026/11/03 08:18:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestDrainGivesUpWhenServerDown1563316562/002/e26312026/11/03 08:18:09 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestDrainGivesUpWhenServerDown1563316562/002/f26322026/11/03 08:18:09 ERROR Drain finished with paths left in queue remaining=102633--- PASS: TestDrainIsolatesPoisonPath (0.01s)2634--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2635--- PASS: TestWorkerPrunesClosureDeps (0.03s)2636--- PASS: TestWorkerUploadsAndRemoves (0.03s)2637--- PASS: TestWorkerSkipsGCdPaths (0.03s)26382026/11/03 08:18:09 ERROR Accept failed error="too many open files"2639--- PASS: TestQueueRemoveLargeClosure (0.04s)2640--- PASS: TestQueueConcurrentWriters (0.05s)26412026/11/03 08:18:09 ERROR Accept failed error="too many open files"26422026/11/03 08:18:09 ERROR Accept failed error="too many open files"26432026/11/03 08:18:09 ERROR Failed to decode request error="read unix /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/hook1935322718/test.sock->: i/o timeout"26442026/11/03 08:18:09 ERROR Failed to write response error="write unix /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/hook1935322718/test.sock->: i/o timeout"2645--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26462026/11/03 08:18:09 ERROR Upload failed error="context deadline exceeded" count=226472026/11/03 08:18:09 ERROR Drain finished with paths left in queue remaining=42648--- PASS: TestDrainTimeout (0.21s)26492026/11/03 08:18:09 ERROR Accept failed error="too many open files"26502026/11/03 08:18:09 ERROR Accept failed error="too many open files"2651--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26522026/11/03 08:18:10 INFO Uploading batch count=126532026/11/03 08:18:10 INFO Uploading batch count=126542026/11/03 08:18:10 INFO Uploading batch count=126552026/11/03 08:18:10 ERROR Upload failed error="upload failed" count=126562026/11/03 08:18:10 INFO Uploading batch count=126572026/11/03 08:18:10 ERROR Upload failed error="upload failed" count=126582026/11/03 08:18:10 INFO Uploading batch count=126592026/11/03 08:18:10 ERROR Upload failed error="upload failed" count=126602026/11/03 08:18:10 INFO Uploading batch count=126612026/11/03 08:18:10 ERROR Upload failed error="upload failed" count=126622026/11/03 08:18:10 ERROR Drain finished with paths left in queue remaining=12663--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2664PASS2665Running signing tests...2666=== RUN TestExternalSigner2667=== PAUSE TestExternalSigner2668=== RUN TestExternalSignerWrongPublicKey2669=== PAUSE TestExternalSignerWrongPublicKey2670=== RUN TestExternalSignerErrors2671=== PAUSE TestExternalSignerErrors2672=== RUN TestExternalSignerRestartsAfterCrash2673=== PAUSE TestExternalSignerRestartsAfterCrash2674=== RUN TestExternalSignerProgramErrorKeepsProcess2675=== PAUSE TestExternalSignerProgramErrorKeepsProcess2676=== RUN TestExternalSignerClose2677=== PAUSE TestExternalSignerClose2678=== RUN TestExternalSignerRejectsInvalidPublicKey2679=== PAUSE TestExternalSignerRejectsInvalidPublicKey2680=== RUN TestExternalSignerCancellation2681=== PAUSE TestExternalSignerCancellation2682=== RUN TestGenerateFingerprint2683=== PAUSE TestGenerateFingerprint2684=== RUN TestParseSigningKey2685=== PAUSE TestParseSigningKey2686=== RUN TestSign2687=== PAUSE TestSign2688=== RUN TestSignBatch2689=== PAUSE TestSignBatch2690=== RUN TestNilKeyPublicKey2691=== PAUSE TestNilKeyPublicKey2692=== RUN TestSignErrors2693=== PAUSE TestSignErrors2694=== CONT TestExternalSigner2695=== CONT TestExternalSignerCancellation2696=== CONT TestExternalSignerProgramErrorKeepsProcess2697=== CONT TestExternalSignerRejectsInvalidPublicKey2698=== CONT TestNilKeyPublicKey2699=== RUN TestExternalSignerRejectsInvalidPublicKey/#002700=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002701=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2702=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2703=== CONT TestExternalSignerErrors2704--- PASS: TestNilKeyPublicKey (0.00s)2705=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2706=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2707=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2708=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2709=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2710=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2711=== CONT TestSignBatch2712=== CONT TestSignErrors2713=== CONT TestParseSigningKey2714=== RUN TestParseSigningKey/valid_32-byte_key2715=== PAUSE TestParseSigningKey/valid_32-byte_key2716=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2717=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2718=== RUN TestParseSigningKey/no_colon2719=== PAUSE TestParseSigningKey/no_colon2720=== RUN TestParseSigningKey/empty_name2721=== PAUSE TestParseSigningKey/empty_name2722=== RUN TestParseSigningKey/invalid_base642723=== PAUSE TestParseSigningKey/invalid_base642724=== CONT TestSign2725=== CONT TestExternalSignerWrongPublicKey2726=== CONT TestExternalSignerRestartsAfterCrash2727=== CONT TestGenerateFingerprint2728=== RUN TestGenerateFingerprint/basic_with_references2729=== PAUSE TestGenerateFingerprint/basic_with_references2730=== RUN TestGenerateFingerprint/no_references2731=== PAUSE TestGenerateFingerprint/no_references2732=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2733=== CONT TestExternalSignerClose2734=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2735=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2736=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2737=== RUN TestGenerateFingerprint/invalid_nar_hash_length2738=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2739=== RUN TestGenerateFingerprint/invalid_store_path_prefix2740=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2741=== RUN TestGenerateFingerprint/invalid_reference_prefix2742=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2743=== CONT TestGenerateFingerprint/basic_with_references2744=== CONT TestGenerateFingerprint/invalid_reference_prefix2745=== CONT TestGenerateFingerprint/invalid_store_path_prefix2746=== CONT TestGenerateFingerprint/invalid_nar_hash_length2747=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2748=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2749=== CONT TestGenerateFingerprint/no_references2750--- PASS: TestGenerateFingerprint (0.00s)2751 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2752 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2753 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2754 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2755 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2756 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2757 --- PASS: TestGenerateFingerprint/no_references (0.00s)2758=== CONT TestExternalSignerRejectsInvalidPublicKey/#002759=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2760=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2761=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2762=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2763--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2764 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2765 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2766 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2767 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2768 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2769=== RUN TestParseSigningKey/wrong_length2770=== RUN TestExternalSignerErrors/invalid_JSON2771=== PAUSE TestParseSigningKey/wrong_length2772=== CONT TestParseSigningKey/valid_32-byte_key2773=== CONT TestParseSigningKey/empty_name2774=== CONT TestParseSigningKey/no_colon2775=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2776=== CONT TestParseSigningKey/invalid_base642777=== PAUSE TestExternalSignerErrors/invalid_JSON2778=== RUN TestExternalSignerErrors/missing_signature_name2779=== PAUSE TestExternalSignerErrors/missing_signature_name2780=== CONT TestParseSigningKey/wrong_length2781=== RUN TestExternalSignerErrors/wrong_signature_name2782=== PAUSE TestExternalSignerErrors/wrong_signature_name2783=== RUN TestExternalSignerErrors/program_error2784=== PAUSE TestExternalSignerErrors/program_error2785=== RUN TestExternalSignerErrors/wrong_id2786=== PAUSE TestExternalSignerErrors/wrong_id2787=== RUN TestExternalSignerErrors/missing_signatures2788=== PAUSE TestExternalSignerErrors/missing_signatures2789=== RUN TestExternalSignerErrors/wrong_signatures_shape2790=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2791=== RUN TestExternalSignerErrors/invalid_signature_base642792=== PAUSE TestExternalSignerErrors/invalid_signature_base642793=== RUN TestExternalSignerErrors/wrong_shape2794=== PAUSE TestExternalSignerErrors/wrong_shape2795=== RUN TestExternalSignerErrors/null2796=== PAUSE TestExternalSignerErrors/null2797=== RUN TestExternalSignerErrors/wrong_signature_length2798=== PAUSE TestExternalSignerErrors/wrong_signature_length2799=== RUN TestExternalSignerErrors/exit_at_startup2800=== PAUSE TestExternalSignerErrors/exit_at_startup2801=== RUN TestExternalSignerErrors/exit_on_request2802=== PAUSE TestExternalSignerErrors/exit_on_request2803=== RUN TestExternalSignerErrors/null_signatures2804=== PAUSE TestExternalSignerErrors/null_signatures2805=== RUN TestExternalSignerErrors/too_few_signatures2806=== PAUSE TestExternalSignerErrors/too_few_signatures2807=== RUN TestExternalSignerErrors/unrequested_key2808=== PAUSE TestExternalSignerErrors/unrequested_key2809=== CONT TestExternalSignerErrors/invalid_JSON2810=== RUN TestSignErrors/nil_key2811=== PAUSE TestSignErrors/nil_key2812=== RUN TestSignErrors/nil_narinfo2813=== PAUSE TestSignErrors/nil_narinfo2814=== RUN TestSignErrors/invalid_narinfo2815=== PAUSE TestSignErrors/invalid_narinfo2816=== RUN TestSignErrors/canceled2817=== PAUSE TestSignErrors/canceled2818=== CONT TestSignErrors/nil_key2819=== CONT TestSignErrors/canceled2820=== CONT TestSignErrors/invalid_narinfo2821--- PASS: TestParseSigningKey (0.00s)2822 --- PASS: TestParseSigningKey/empty_name (0.00s)2823 --- PASS: TestParseSigningKey/no_colon (0.00s)2824 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2825 --- PASS: TestParseSigningKey/wrong_length (0.00s)2826 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2827 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2828=== CONT TestSignErrors/nil_narinfo2829=== CONT TestExternalSignerErrors/unrequested_key2830--- PASS: TestSignErrors (0.00s)2831 --- PASS: TestSignErrors/nil_key (0.00s)2832 --- PASS: TestSignErrors/canceled (0.00s)2833 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2834 --- PASS: TestSignErrors/nil_narinfo (0.00s)2835=== CONT TestExternalSignerErrors/wrong_shape2836=== CONT TestExternalSignerErrors/invalid_signature_base642837--- PASS: TestSignBatch (0.00s)2838=== CONT TestExternalSignerErrors/wrong_id2839=== CONT TestExternalSignerErrors/too_few_signatures2840=== CONT TestExternalSignerErrors/exit_at_startup2841=== CONT TestExternalSignerErrors/program_error2842=== CONT TestExternalSignerErrors/wrong_signatures_shape2843--- PASS: TestSign (0.00s)2844=== CONT TestExternalSignerErrors/wrong_signature_name2845=== CONT TestExternalSignerErrors/wrong_signature_length2846=== CONT TestExternalSignerErrors/null_signatures2847=== CONT TestExternalSignerErrors/missing_signatures2848=== CONT TestExternalSignerErrors/missing_signature_name2849=== CONT TestExternalSignerErrors/null2850=== CONT TestExternalSignerErrors/exit_on_request2851--- PASS: TestExternalSigner (0.11s)2852--- PASS: TestExternalSignerCancellation (0.20s)2853--- PASS: TestExternalSignerProgramErrorKeepsProcess (0.26s)2854--- PASS: TestExternalSignerWrongPublicKey (0.65s)2855--- PASS: TestExternalSignerRestartsAfterCrash (0.74s)2856/private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestExternalSignerRestartsAfterCrash1591499156/001/sign program: line 7: /private/var/tb/4/scratch/3f30ff2c29ccf99c/build/TestExternalSignerRestartsAfterCrash1591499156/001/sign program.starts: No such file or directory2857--- PASS: TestExternalSignerClose (1.36s)2858--- PASS: TestExternalSignerErrors (0.00s)2859 --- PASS: TestExternalSignerErrors/wrong_signature_name (0.33s)2860 --- PASS: TestExternalSignerErrors/exit_at_startup (0.41s)2861 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (0.49s)2862 --- PASS: TestExternalSignerErrors/unrequested_key (0.56s)2863 --- PASS: TestExternalSignerErrors/wrong_shape (0.80s)2864 --- PASS: TestExternalSignerErrors/missing_signature_name (0.88s)2865 --- PASS: TestExternalSignerErrors/exit_on_request (0.96s)2866 --- PASS: TestExternalSignerErrors/null_signatures (1.04s)2867 --- PASS: TestExternalSignerErrors/null (1.12s)2868 --- PASS: TestExternalSignerErrors/missing_signatures (1.20s)2869 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.28s)2870 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.43s)2871 --- PASS: TestExternalSignerErrors/program_error (1.51s)2872 --- PASS: TestExternalSignerErrors/too_few_signatures (1.59s)2873 --- PASS: TestExternalSignerErrors/invalid_JSON (1.67s)2874 --- PASS: TestExternalSignerErrors/wrong_id (1.75s)2875PASS2876Running OpenBao signer tests...2877=== RUN TestSign2878=== PAUSE TestSign2879=== RUN TestSignErrors2880=== PAUSE TestSignErrors2881=== RUN TestServe2882=== PAUSE TestServe2883=== RUN TestServeRejectsGarbage2884=== PAUSE TestServeRejectsGarbage2885=== CONT TestSign2886=== CONT TestServe2887=== CONT TestServeRejectsGarbage2888--- PASS: TestServeRejectsGarbage (0.00s)2889=== CONT TestSignErrors2890=== RUN TestSignErrors/invalid_base642891=== PAUSE TestSignErrors/invalid_base642892=== RUN TestSignErrors/http_error2893=== PAUSE TestSignErrors/http_error2894=== RUN TestSignErrors/invalid_json2895=== PAUSE TestSignErrors/invalid_json2896=== RUN TestSignErrors/no_prefix2897=== PAUSE TestSignErrors/no_prefix2898=== CONT TestSignErrors/invalid_base642899=== CONT TestSignErrors/invalid_json2900=== CONT TestSignErrors/http_error2901--- PASS: TestServe (0.00s)2902=== CONT TestSignErrors/no_prefix2903--- PASS: TestSign (0.00s)2904--- PASS: TestSignErrors (0.00s)2905 --- PASS: TestSignErrors/http_error (0.00s)2906 --- PASS: TestSignErrors/no_prefix (0.00s)2907 --- PASS: TestSignErrors/invalid_json (0.00s)2908 --- PASS: TestSignErrors/invalid_base64 (0.00s)2909PASS