niks3-go-unit-tests
checks.aarch64-darwin.go-unit-tests
· build #462
· 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.07s)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 TestScriptTokenEmptyToken117=== CONT TestFileTokenMissing118--- PASS: TestFileTokenMissing (0.00s)119=== CONT TestRetryTimeoutOutlastsMaxRetries120=== CONT TestScriptTokenCachesUntilRefresh121=== CONT TestScriptTokenNoExpiryRerunsEveryCall122=== CONT TestFileTokenEmpty123=== CONT TestRateLimiterFeedback124=== RUN TestRateLimiterFeedback/429_enables_limiter125=== PAUSE TestRateLimiterFeedback/429_enables_limiter126=== RUN TestRateLimiterFeedback/503_enables_limiter127=== PAUSE TestRateLimiterFeedback/503_enables_limiter128=== RUN TestRateLimiterFeedback/200_does_not_enable_limiter129=== PAUSE TestRateLimiterFeedback/200_does_not_enable_limiter130=== RUN TestRateLimiterFeedback/400_does_not_enable_limiter131=== PAUSE TestRateLimiterFeedback/400_does_not_enable_limiter132--- PASS: TestFileTokenEmpty (0.00s)133=== CONT TestFileTokenReadsAndCaches134=== CONT TestStaticToken135=== CONT TestSetClientTLSErrors136=== CONT TestSetClientTLSDoesNotMutateDefaultTransport137=== CONT TestSetClientTLS138=== CONT TestStreamPushStopsWhenCanceled139=== CONT TestClientSignaturesByStorePath140=== CONT TestStreamPushReportsSkippedPaths141=== CONT TestStreamPushReportsSignatures142=== CONT TestStreamPushRequestLine143=== CONT TestStreamPushGivesUpOnDeadServer144=== CONT TestStreamPushIsolatesFailures145=== CONT TestStreamPushBatchesUnderLoad146=== CONT TestStreamPushReportsEveryPath147=== CONT TestShellSplitErrors148=== CONT TestShellSplit149=== CONT TestDoWithRetry_FinalResponseBodyReadable150=== CONT TestResolveStorePath151--- PASS: TestStaticToken (0.00s)152=== CONT TestRegisterUploadedObject_BoundedAgainstSilentServer153--- PASS: TestStreamPushStopsWhenCanceled (0.00s)154=== CONT TestRateLimiterFeedback_400DoesNotCountAsSuccess1552026/11/06 06:57:31 WARN Rate limiter enabled after throttle name=server-test rate=5156--- PASS: TestClientSignaturesByStorePath (0.00s)157=== CONT TestDumpPathMatchesNix158=== CONT TestDoWithRetry_BodyReplayedViaGetBody159--- PASS: TestStreamPushReportsSkippedPaths (0.00s)160=== CONT TestPathInfoCACompatibility161=== RUN TestPathInfoCACompatibility/null_ca_field162=== PAUSE TestPathInfoCACompatibility/null_ca_field163=== RUN TestPathInfoCACompatibility/old_string_format_-_text164=== PAUSE TestPathInfoCACompatibility/old_string_format_-_text165=== RUN TestPathInfoCACompatibility/old_string_format_-_fixed_recursive166=== PAUSE TestPathInfoCACompatibility/old_string_format_-_fixed_recursive167=== RUN TestPathInfoCACompatibility/new_structured_format_-_text168=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_text169=== RUN TestPathInfoCACompatibility/new_structured_format_-_nar_method170=== PAUSE TestPathInfoCACompatibility/new_structured_format_-_nar_method171=== CONT TestParsePathInfoJSONMultiplePaths1722026/11/06 06:57:31 ERROR Upload failed error=boom count=11732026/11/06 06:57:31 ERROR Upload failed error="bad path" count=3174=== RUN TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths175--- PASS: TestResolveStorePath (0.00s)176--- PASS: TestFileTokenReadsAndCaches (0.00s)177=== CONT TestParsePathInfoJSON178=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=false179=== CONT TestPathInfoHashCompatibility180--- PASS: TestShellSplitErrors (0.00s)1812026/11/06 06:57:31 ERROR Upload failed error="connection refused" count=201822026/11/06 06:57:31 ERROR Server seems unavailable, giving up on batch untried=17183=== CONT TestGetStorePathHash184=== RUN TestGetStorePathHash/valid_store_path185=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=false186=== RUN TestStreamPushBatchesUnderLoad/oneAtATime=true187=== PAUSE TestStreamPushBatchesUnderLoad/oneAtATime=true188=== PAUSE TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths189=== RUN TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths190=== RUN TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)191=== PAUSE TestGetStorePathHash/valid_store_path192--- PASS: TestStreamPushGivesUpOnDeadServer (0.00s)193--- PASS: TestSetClientTLSDoesNotMutateDefaultTransport (0.00s)194=== CONT TestEncodeNixBase32WithRealHash195=== CONT TestEncodeNixBase32196=== CONT TestConvertHashToNix32197=== RUN TestGetStorePathHash/basename_without_hyphen_should_error198=== PAUSE TestGetStorePathHash/basename_without_hyphen_should_error199=== RUN TestGetStorePathHash/hash_with_invalid_characters_should_error200--- PASS: TestEncodeNixBase32WithRealHash (0.00s)201=== CONT TestDumpPathWriterError202=== RUN TestParsePathInfoJSON/Nix_format203=== PAUSE TestParsePathInfoJSON/Nix_format204=== RUN TestParsePathInfoJSON/Lix_format205=== PAUSE TestParsePathInfoJSON/Lix_format206=== RUN TestParsePathInfoJSON/empty_input207=== PAUSE TestParsePathInfoJSON/empty_input208=== RUN TestEncodeNixBase32/test_string_hash209=== PAUSE TestEncodeNixBase32/test_string_hash210=== RUN TestEncodeNixBase32/empty_input211=== PAUSE TestEncodeNixBase32/empty_input212=== RUN TestParsePathInfoJSON/whitespace_only213=== PAUSE TestParsePathInfoJSON/whitespace_only214=== CONT TestDumpPathSingleFile215=== RUN TestParsePathInfoJSON/invalid_JSON216=== PAUSE TestParsePathInfoJSON/invalid_JSON217--- PASS: TestShellSplit (0.00s)218=== CONT TestScriptTokenEmptyCommand219--- PASS: TestScriptTokenEmptyCommand (0.00s)220=== CONT TestFilterOversizedClosures221=== RUN TestFilterOversizedClosures/no_limit_keeps_everything222=== PAUSE TestFilterOversizedClosures/no_limit_keeps_everything223=== RUN TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped224=== PAUSE TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped225=== RUN TestFilterOversizedClosures/all_closures_skipped226=== PAUSE TestFilterOversizedClosures/all_closures_skipped227=== RUN TestSetClientTLS/rejects_connection_without_client_cert228=== PAUSE TestSetClientTLS/rejects_connection_without_client_cert229=== RUN TestSetClientTLS/succeeds_with_client_cert_and_CA230=== PAUSE TestSetClientTLS/succeeds_with_client_cert_and_CA231=== CONT TestUploadMultipart_SupersededByPeer232=== RUN TestUploadMultipart_SupersededByPeer/exists233=== PAUSE TestUploadMultipart_SupersededByPeer/exists234=== RUN TestUploadMultipart_SupersededByPeer/missing235=== PAUSE TestUploadMultipart_SupersededByPeer/missing236=== CONT TestSupersededNARStillUploadsListing237=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)238=== RUN TestPathInfoHashCompatibility/old_string_format_with_colon239=== PAUSE TestPathInfoHashCompatibility/old_string_format_with_colon240=== RUN TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI241=== PAUSE TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI242=== RUN TestPathInfoHashCompatibility/new_structured_format_with_sha512243=== PAUSE TestPathInfoHashCompatibility/new_structured_format_with_sha512244=== RUN TestSetClientTLS/preserves_debug_logging_transport245=== PAUSE TestSetClientTLS/preserves_debug_logging_transport246=== CONT TestUploadMultipart_FailedPartBufferNotReused247=== CONT TestScriptTokenScriptFails2482026/11/06 06:57:31 ERROR Upload failed error=boom count=1249=== RUN TestConvertHashToNix32/SRI_format_to_Nix32250--- PASS: TestStreamPushReportsEveryPath (0.00s)251=== RUN TestSupersededNARStillUploadsListing/small_NAR252=== CONT TestPartSizeForNAR253=== RUN TestPartSizeForNAR/zero_stays_at_minimum254=== PAUSE TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths255=== PAUSE TestGetStorePathHash/hash_with_invalid_characters_should_error256=== CONT TestUploadMultipart_PartsInParallel2572026/11/06 06:57:31 WARN Rate limiter enabled after throttle name=server-test rate=52582026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:527672592026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:52777260=== CONT TestRunGarbageCollection_FinishedOnAnotherReplica2612026/11/06 06:57:31 WARN Rate limiter enabled after throttle name=server-test rate=5262--- PASS: TestScriptTokenEmptyToken (0.01s)263--- PASS: TestStreamPushReportsSignatures (0.01s)264--- PASS: TestDoServerRequestAttachesToken (0.02s)265=== CONT TestCaseHackSuffix266=== PAUSE TestPartSizeForNAR/zero_stays_at_minimum267=== PAUSE TestConvertHashToNix32/SRI_format_to_Nix32268=== CONT TestRunGarbageCollection_NotFoundAfterLocalRun269=== CONT TestScriptTokenBadJSON2702026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:527752712026/11/06 06:57:31 WARN Rate limiter backed off name=server-test rate=5272--- PASS: TestDoWithRetry_FinalResponseBodyReadable (0.01s)273=== CONT TestRegisterUploadedObjectReusesConnections2742026/11/06 06:57:31 INFO Garbage collection started2752026/11/06 06:57:31 WARN Rate limiter backed off name=server-test rate=52762026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=2 backoff=0s status=503 url=http://127.0.0.1:527752772026/11/06 06:57:31 INFO Garbage collection started278--- PASS: TestStreamPushIsolatesFailures (0.01s)279=== CONT TestUploadBuildLog_FileBodyReplayedOnRetry280=== RUN TestGetStorePathHash/hash_with_wrong_length_should_error281=== RUN TestPartSizeForNAR/small_stays_at_minimum282=== PAUSE TestPartSizeForNAR/small_stays_at_minimum283=== RUN TestPartSizeForNAR/80_GiB_fits_at_minimum284=== PAUSE TestPartSizeForNAR/80_GiB_fits_at_minimum285=== RUN TestPartSizeForNAR/115_GiB_needs_larger_parts286=== PAUSE TestPartSizeForNAR/115_GiB_needs_larger_parts287=== RUN TestPartSizeForNAR/1_TiB288=== PAUSE TestPartSizeForNAR/1_TiB289=== PAUSE TestSupersededNARStillUploadsListing/small_NAR290=== RUN TestSupersededNARStillUploadsListing/dump_cut_short291=== PAUSE TestSupersededNARStillUploadsListing/dump_cut_short292=== RUN TestSupersededNARStillUploadsListing/listing_upload_fails293=== PAUSE TestSupersededNARStillUploadsListing/listing_upload_fails294=== PAUSE TestGetStorePathHash/hash_with_wrong_length_should_error295=== CONT TestRateLimiterFeedback/429_enables_limiter296=== CONT TestRateLimiterFeedback/200_does_not_enable_limiter2972026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:52767298=== RUN TestConvertHashToNix32/already_Nix32_format299=== PAUSE TestConvertHashToNix32/already_Nix32_format300=== RUN TestConvertHashToNix32/invalid_format301=== PAUSE TestConvertHashToNix32/invalid_format302=== RUN TestSetClientTLSErrors/missing_cert_file303=== PAUSE TestSetClientTLSErrors/missing_cert_file304=== RUN TestSetClientTLSErrors/missing_key_file305=== PAUSE TestSetClientTLSErrors/missing_key_file306=== CONT TestRateLimiterFeedback/400_does_not_enable_limiter307=== RUN TestPartSizeForNAR/5_TiB_S3_max_object308=== PAUSE TestPartSizeForNAR/5_TiB_S3_max_object309=== RUN TestSetClientTLSErrors/missing_ca_file3102026/11/06 06:57:31 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=0311=== PAUSE TestSetClientTLSErrors/missing_ca_file312=== RUN TestSetClientTLSErrors/invalid_ca_file313=== PAUSE TestSetClientTLSErrors/invalid_ca_file314=== RUN TestPartSizeForNAR/capped_at_5_GiB315=== PAUSE TestPartSizeForNAR/capped_at_5_GiB316=== CONT TestRateLimiterFeedback/503_enables_limiter317--- PASS: TestRunGarbageCollection_NotFoundAfterLocalRun (0.00s)318=== CONT TestPathInfoCACompatibility/null_ca_field319=== CONT TestPathInfoCACompatibility/new_structured_format_-_text320=== CONT TestPathInfoCACompatibility/old_string_format_-_fixed_recursive321=== CONT TestPathInfoCACompatibility/old_string_format_-_text322=== CONT TestPathInfoCACompatibility/new_structured_format_-_nar_method323--- PASS: TestPathInfoCACompatibility (0.00s)324 --- PASS: TestPathInfoCACompatibility/null_ca_field (0.00s)325 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_text (0.00s)326 --- PASS: TestPathInfoCACompatibility/old_string_format_-_fixed_recursive (0.00s)327 --- PASS: TestPathInfoCACompatibility/old_string_format_-_text (0.00s)328 --- PASS: TestPathInfoCACompatibility/new_structured_format_-_nar_method (0.00s)329=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=false330=== CONT TestStreamPushBatchesUnderLoad/oneAtATime=true331=== CONT TestEncodeNixBase32/test_string_hash332=== CONT TestEncodeNixBase32/empty_input333--- PASS: TestEncodeNixBase32 (0.00s)334 --- PASS: TestEncodeNixBase32/test_string_hash (0.00s)335 --- PASS: TestEncodeNixBase32/empty_input (0.00s)336--- PASS: TestStreamPushBatchesUnderLoad (0.00s)337 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=false (0.00s)338 --- PASS: TestStreamPushBatchesUnderLoad/oneAtATime=true (0.00s)339=== CONT TestParsePathInfoJSON/Nix_format340=== CONT TestParsePathInfoJSON/invalid_JSON341=== CONT TestParsePathInfoJSON/empty_input342=== CONT TestParsePathInfoJSON/Lix_format343=== CONT TestParsePathInfoJSON/whitespace_only344--- PASS: TestParsePathInfoJSON (0.00s)345 --- PASS: TestParsePathInfoJSON/Nix_format (0.00s)346 --- PASS: TestParsePathInfoJSON/invalid_JSON (0.00s)347 --- PASS: TestParsePathInfoJSON/empty_input (0.00s)348 --- PASS: TestParsePathInfoJSON/Lix_format (0.00s)349 --- PASS: TestParsePathInfoJSON/whitespace_only (0.00s)350=== CONT TestFilterOversizedClosures/no_limit_keeps_everything351=== CONT TestUploadMultipart_SupersededByPeer/exists352=== CONT TestFilterOversizedClosures/all_closures_skipped353=== CONT TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped354=== CONT TestUploadMultipart_SupersededByPeer/missing3552026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=1 backoff=1ms status=502 url=http://127.0.0.1:527673562026/11/06 06:57:31 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=50357=== CONT TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI)3582026/11/06 06:57:31 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=2000359--- PASS: TestFilterOversizedClosures (0.00s)360 --- PASS: TestFilterOversizedClosures/no_limit_keeps_everything (0.00s)361 --- PASS: TestFilterOversizedClosures/all_closures_skipped (0.00s)362 --- PASS: TestFilterOversizedClosures/closure_with_oversized_dependency_is_skipped (0.00s)363=== CONT TestSetClientTLS/rejects_connection_without_client_cert364=== CONT TestPathInfoHashCompatibility/new_structured_format_with_sha512365=== CONT TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI366=== CONT TestPathInfoHashCompatibility/old_string_format_with_colon367--- PASS: TestPathInfoHashCompatibility (0.00s)368 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_dash_(SRI) (0.00s)369 --- PASS: TestPathInfoHashCompatibility/new_structured_format_with_sha512 (0.00s)370 --- PASS: TestPathInfoHashCompatibility/new_structured_format_-_converts_to_SRI (0.00s)371 --- PASS: TestPathInfoHashCompatibility/old_string_format_with_colon (0.00s)372=== CONT TestSetClientTLS/preserves_debug_logging_transport3732026/11/06 06:57:31 WARN Rate limiter enabled after throttle name=server-test rate=53742026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=429 url=http://127.0.0.1:527873752026/11/06 06:57:31 WARN Garbage collection finished on another replica. Its statistics are not available here376--- PASS: TestRunGarbageCollection_FinishedOnAnotherReplica (0.01s)377=== CONT TestSetClientTLS/succeeds_with_client_cert_and_CA3782026/11/06 06:57:31 WARN Rate limiter enabled after throttle name=server-test rate=53792026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:528113802026/11/06 06:57:31 WARN Rate limiter backed off name=server-test rate=53812026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=2 backoff=1ms status=502 url=http://127.0.0.1:52767382=== CONT TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths383=== CONT TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths384--- PASS: TestParsePathInfoJSONMultiplePaths (0.00s)385 --- PASS: TestParsePathInfoJSONMultiplePaths/Nix_multiple_paths (0.00s)386 --- PASS: TestParsePathInfoJSONMultiplePaths/Lix_multiple_paths (0.00s)387=== CONT TestSupersededNARStillUploadsListing/small_NAR3882026/11/06 06:57:31 WARN Rate limiter backed off name=server-test rate=53892026/11/06 06:57:31 WARN Rate limiter enabled after throttle name=s3-test rate=53902026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=1 backoff=0s status=503 url=http://127.0.0.1:52818391--- PASS: TestDoWithRetry_BodyReplayedViaGetBody (0.03s)392=== CONT TestSupersededNARStillUploadsListing/dump_cut_short393--- PASS: TestRateLimiterFeedback (0.00s)394 --- PASS: TestRateLimiterFeedback/200_does_not_enable_limiter (0.00s)395 --- PASS: TestRateLimiterFeedback/400_does_not_enable_limiter (0.00s)396 --- PASS: TestRateLimiterFeedback/503_enables_limiter (0.00s)397 --- PASS: TestRateLimiterFeedback/429_enables_limiter (0.01s)398=== CONT TestGetStorePathHash/valid_store_path399=== CONT TestSupersededNARStillUploadsListing/listing_upload_fails4002026/11/06 06:57:31 INFO Uploading abc-hello (1.0GB)401=== CONT TestGetStorePathHash/hash_with_wrong_length_should_error402=== CONT TestGetStorePathHash/hash_with_invalid_characters_should_error403=== CONT TestGetStorePathHash/basename_without_hyphen_should_error404--- PASS: TestGetStorePathHash (0.01s)405 --- PASS: TestGetStorePathHash/valid_store_path (0.00s)406 --- PASS: TestGetStorePathHash/hash_with_wrong_length_should_error (0.00s)407 --- PASS: TestGetStorePathHash/hash_with_invalid_characters_should_error (0.00s)408 --- PASS: TestGetStorePathHash/basename_without_hyphen_should_error (0.00s)409=== CONT TestConvertHashToNix32/SRI_format_to_Nix32410=== CONT TestConvertHashToNix32/invalid_format411=== CONT TestConvertHashToNix32/already_Nix32_format412--- PASS: TestConvertHashToNix32 (0.01s)413 --- PASS: TestConvertHashToNix32/SRI_format_to_Nix32 (0.00s)414 --- PASS: TestConvertHashToNix32/invalid_format (0.00s)415 --- PASS: TestConvertHashToNix32/already_Nix32_format (0.00s)416=== CONT TestSetClientTLSErrors/missing_cert_file417=== CONT TestPartSizeForNAR/zero_stays_at_minimum418=== CONT TestSetClientTLSErrors/invalid_ca_file419=== CONT TestSetClientTLSErrors/missing_ca_file420=== CONT TestSetClientTLSErrors/missing_key_file421=== CONT TestPartSizeForNAR/capped_at_5_GiB422=== CONT TestPartSizeForNAR/5_TiB_S3_max_object423=== CONT TestPartSizeForNAR/1_TiB424=== CONT TestPartSizeForNAR/80_GiB_fits_at_minimum425=== CONT TestPartSizeForNAR/small_stays_at_minimum426=== CONT TestPartSizeForNAR/115_GiB_needs_larger_parts427--- PASS: TestUploadBuildLog_FileBodyReplayedOnRetry (0.02s)428--- PASS: TestSetClientTLSErrors (0.02s)429 --- PASS: TestSetClientTLSErrors/missing_cert_file (0.00s)430 --- PASS: TestSetClientTLSErrors/invalid_ca_file (0.00s)431 --- PASS: TestSetClientTLSErrors/missing_ca_file (0.00s)432 --- PASS: TestSetClientTLSErrors/missing_key_file (0.00s)433--- PASS: TestPartSizeForNAR (0.01s)434 --- PASS: TestPartSizeForNAR/zero_stays_at_minimum (0.00s)435 --- PASS: TestPartSizeForNAR/capped_at_5_GiB (0.00s)436 --- PASS: TestPartSizeForNAR/5_TiB_S3_max_object (0.00s)437 --- PASS: TestPartSizeForNAR/1_TiB (0.00s)438 --- PASS: TestPartSizeForNAR/80_GiB_fits_at_minimum (0.00s)439 --- PASS: TestPartSizeForNAR/small_stays_at_minimum (0.00s)440 --- PASS: TestPartSizeForNAR/115_GiB_needs_larger_parts (0.00s)441--- PASS: TestScriptTokenScriptFails (0.04s)442--- PASS: TestUploadMultipart_SupersededByPeer (0.00s)443 --- PASS: TestUploadMultipart_SupersededByPeer/exists (0.01s)444 --- PASS: TestUploadMultipart_SupersededByPeer/missing (0.02s)4452026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=3 backoff=1ms status=502 url=http://127.0.0.1:527674462026/11/06 06:57:31 WARN Rate limiter enabled after throttle name=s3-test rate=54472026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=4 backoff=1ms status=502 url=http://127.0.0.1:52767448--- PASS: TestStreamPushRequestLine (0.04s)449--- PASS: TestScriptTokenCachesUntilRefresh (0.05s)4502026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=5 backoff=1ms status=502 url=http://127.0.0.1:52767451--- PASS: TestScriptTokenBadJSON (0.04s)4522026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=6 backoff=1ms status=502 url=http://127.0.0.1:52767453--- PASS: TestScriptTokenNoExpiryRerunsEveryCall (0.06s)4542026/11/06 06:57:31 INFO Uploading abc-hello (1.0GB)4552026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=7 backoff=1ms status=502 url=http://127.0.0.1:527674562026/11/06 06:57:31 INFO Uploading abc-hello (1.0GB)4572026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=8 backoff=1ms status=502 url=http://127.0.0.1:527674582026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=9 backoff=1ms status=502 url=http://127.0.0.1:527674592026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=10 backoff=1ms status=502 url=http://127.0.0.1:52767460--- PASS: TestRegisterUploadedObjectReusesConnections (0.08s)4612026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=11 backoff=1ms status=502 url=http://127.0.0.1:527674622026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=12 backoff=1ms status=502 url=http://127.0.0.1:527674632026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=13 backoff=1ms status=502 url=http://127.0.0.1:527674642026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=14 backoff=1ms status=502 url=http://127.0.0.1:527674652026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=15 backoff=1ms status=502 url=http://127.0.0.1:527674662026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=16 backoff=1ms status=502 url=http://127.0.0.1:527674672026/11/06 06:57:31 WARN Request returned retryable status, retrying attempt=17 backoff=1ms status=502 url=http://127.0.0.1:52767468--- PASS: TestRetryTimeoutOutlastsMaxRetries (0.12s)469--- PASS: TestDumpPathWriterError (0.11s)4702026/11/06 06:57:31 WARN Request failed, retrying attempt=1 backoff=100ms error="Put \"http://127.0.0.1:52866/part/2\": uploading part 1: server returned 404: no such upload\n" url=http://127.0.0.1:52866/part/24712026/11/06 06:57:31 ERROR Failed to close zstd encoder error="io: read/write on closed pipe"472--- PASS: TestCaseHackSuffix (0.11s)4732026/11/06 06:57:31 http: TLS handshake error from 127.0.0.1:52848: remote error: tls: bad certificate474--- PASS: TestSetClientTLS (0.00s)475 --- PASS: TestSetClientTLS/preserves_debug_logging_transport (0.06s)476 --- PASS: TestSetClientTLS/succeeds_with_client_cert_and_CA (0.07s)477 --- PASS: TestSetClientTLS/rejects_connection_without_client_cert (0.11s)478--- PASS: TestDumpPathSingleFile (0.12s)479--- PASS: TestDumpPathMatchesNix (0.15s)480--- PASS: TestUploadMultipart_FailedPartBufferNotReused (0.60s)481--- PASS: TestSupersededNARStillUploadsListing (0.01s)482 --- PASS: TestSupersededNARStillUploadsListing/listing_upload_fails (0.01s)483 --- PASS: TestSupersededNARStillUploadsListing/small_NAR (0.04s)484 --- PASS: TestSupersededNARStillUploadsListing/dump_cut_short (0.58s)485--- PASS: TestUploadMultipart_PartsInParallel (0.65s)4862026/11/06 06:57:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52769/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52769/api/uploads/complete4872026/11/06 06:57:32 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4882026/11/06 06:57:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52769/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52769/api/uploads/complete489--- PASS: TestRateLimiterFeedback_400DoesNotCountAsSuccess (1.00s)4902026/11/06 06:57:32 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"4912026/11/06 06:57:32 WARN Request failed, retrying attempt=1 backoff=100ms error="Post \"http://127.0.0.1:52769/api/uploads/complete\": context deadline exceeded" url=http://127.0.0.1:52769/api/uploads/complete4922026/11/06 06:57:32 WARN Failed to register uploaded object key=abc.narinfo error="sending request: context canceled during retry: context deadline exceeded"493--- PASS: TestRegisterUploadedObject_BoundedAgainstSilentServer (1.00s)494PASS495Running server tests...496The files belonging to this database system will be owned by user "_tribuchetbld7".497This user must also own the server process.498499The database cluster will be initialized with locale "C".500The default database encoding has accordingly been set to "SQL_ASCII".501The default text search configuration will be set to "english".502503Data page checksums are enabled.504505creating directory /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/postgres3824695625/data ... ok506creating subdirectories ... ok507selecting dynamic shared memory implementation ... posix508selecting default "max_connections" ... 100509selecting default "shared_buffers" ... 128MB510selecting default time zone ... UTC511creating configuration files ... ok512running bootstrap script ... ok513performing post-bootstrap initialization ... ok514syncing data to disk ... ok515516initdb: warning: enabling "trust" authentication for local connections517initdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.518519Success. You can now start the database server using:520521 pg_ctl -D /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/postgres3824695625/data -l logfile start522523/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/postgres3824695625:5432 - no response5242026-11-06 06:57:33.729 UTC [77775] LOG: starting PostgreSQL 18.6 on aarch64-apple-darwin25.6.0, compiled by clang version 21.1.8, 64-bit5252026-11-06 06:57:33.729 UTC [77775] LOG: listening on Unix socket "/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/postgres3824695625/.s.PGSQL.5432"5262026-11-06 06:57:33.732 UTC [77782] LOG: database system was shut down at 2026-11-06 06:57:33 UTC5272026-11-06 06:57:33.733 UTC [77775] LOG: database system is ready to accept connections528/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/postgres3824695625:5432 - accepting connections529{"timestamp":"2026-11-06T06:57:33.969906Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"37073fb4-7360-4655-9af0-1a118c299945","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":13,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}530{"timestamp":"2026-11-06T06:57:34.078536Z","level":"ERROR","message":"HTTP request completed","event":"http_request_completed","component":"server","subsystem":"http","request_id":"42fb993f-8b91-4521-999c-0c3d05f2aa7f","trace_id":"unknown","span_id":"unknown","peer_addr":"127.0.0.1","method":"GET","uri":"/health/ready","status_code":503,"suppressed_errors":0,"duration_ms":0,"result":"server_error","target":"rustfs::server::http","filename":"rustfs/src/server/layer.rs","line_number":502,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}531=== RUN TestService_AuthMiddleware532=== PAUSE TestService_AuthMiddleware533=== RUN TestService_AuthMiddleware_MTLSProxyHeader534=== PAUSE TestService_AuthMiddleware_MTLSProxyHeader535=== RUN TestService_AuthMiddleware_MTLSBoundSubjects536=== PAUSE TestService_AuthMiddleware_MTLSBoundSubjects537=== RUN TestService_ReadAuthMiddleware538=== PAUSE TestService_ReadAuthMiddleware539=== RUN TestService_AuthMiddleware_OIDC540=== PAUSE TestService_AuthMiddleware_OIDC541=== RUN TestService_RequireScope_OIDC542=== PAUSE TestService_RequireScope_OIDC543=== RUN TestService_ReadScope_PublicByDefault544=== PAUSE TestService_ReadScope_PublicByDefault545=== RUN TestCacheConfigHandler546=== PAUSE TestCacheConfigHandler547=== RUN TestCacheStatsHandler548=== PAUSE TestCacheStatsHandler549=== RUN TestClientCADerivations550=== PAUSE TestClientCADerivations551=== RUN TestClientErrorHandling552=== PAUSE TestClientErrorHandling553=== RUN TestClientIntegration554=== PAUSE TestClientIntegration555=== RUN TestClientMultipleUploads556=== PAUSE TestClientMultipleUploads557=== RUN TestClientWithDependencies558=== PAUSE TestClientWithDependencies559=== RUN TestClientSharedPathCommittedMidPush560=== PAUSE TestClientSharedPathCommittedMidPush561=== RUN TestPinProtectsFromGC562=== PAUSE TestPinProtectsFromGC563=== RUN TestClientPushesUseOnePush564=== PAUSE TestClientPushesUseOnePush565=== RUN TestClientFallsBackToClosures566=== PAUSE TestClientFallsBackToClosures567=== RUN TestDeleteClosuresRacingPins568=== PAUSE TestDeleteClosuresRacingPins569=== RUN TestConcurrentCommitsSharingObjectsDoNotDeadlock570=== PAUSE TestConcurrentCommitsSharingObjectsDoNotDeadlock571=== RUN TestResolveDBConnectionString572=== PAUSE TestResolveDBConnectionString573=== RUN TestConnectWaitsForAPeerMigration574=== PAUSE TestConnectWaitsForAPeerMigration575=== RUN TestLeadElectsOneAndHandsOver576=== PAUSE TestLeadElectsOneAndHandsOver577=== RUN TestLeadIncumbentWinsAfterRestart5782026/11/06 06:57:34 INFO lead: acquired remote=192.0.2.1:12345792026/11/06 06:57:35 INFO lead: released remote=192.0.2.1:12345802026/11/06 06:57:35 INFO lead: acquired remote=192.0.2.1:12345812026/11/06 06:57:36 INFO lead: released remote=192.0.2.1:1234582--- PASS: TestLeadIncumbentWinsAfterRestart (2.07s)583=== RUN TestLeadIncumbentAnnouncesAtOnce584=== PAUSE TestLeadIncumbentAnnouncesAtOnce585=== RUN TestLeadEndsOnShutdown586=== PAUSE TestLeadEndsOnShutdown587=== RUN TestLeadEndsWhenItsConnectionHangs5882026/11/06 06:57:36 INFO lead: acquired remote=192.0.2.1:12345892026-11-06 06:57:37.591 UTC [77833] FATAL: terminating connection due to administrator command5902026/11/06 06:57:37 INFO lead: acquired remote=192.0.2.1:12345912026/11/06 06:57:38 WARN lead: lock connection lost error="timeout: context deadline exceeded"5922026/11/06 06:57:38 INFO lead: released remote=192.0.2.1:12345932026/11/06 06:57:38 INFO lead: released remote=192.0.2.1:1234594--- PASS: TestLeadEndsWhenItsConnectionHangs (2.74s)595=== RUN TestGCAdvisoryLockBlocksConcurrentRun596=== PAUSE TestGCAdvisoryLockBlocksConcurrentRun597=== RUN TestGCBugBareHashReferences598=== PAUSE TestGCBugBareHashReferences599=== RUN TestGCMetrics600=== PAUSE TestGCMetrics601=== RUN TestPushDedupSurvivesConcurrentGC602=== PAUSE TestPushDedupSurvivesConcurrentGC603=== RUN TestDeduplicatedObjectsRecordedAsPending604=== PAUSE TestDeduplicatedObjectsRecordedAsPending605=== RUN TestGCSweepSkipsPendingObjects606=== PAUSE TestGCSweepSkipsPendingObjects607=== RUN TestTombstonedObjectOfferedWithoutWaiting608=== PAUSE TestTombstonedObjectOfferedWithoutWaiting609=== RUN TestGCSweepDeliversEachKeyOnce610=== PAUSE TestGCSweepDeliversEachKeyOnce611=== RUN TestCreatePendingClosureVerifyS3FailureReleasesConnection612=== PAUSE TestCreatePendingClosureVerifyS3FailureReleasesConnection613=== RUN TestForceGCDuringPushOffersSweptObject614=== PAUSE TestForceGCDuringPushOffersSweptObject615=== RUN TestFailedS3DeleteKeepsTombstone616=== PAUSE TestFailedS3DeleteKeepsTombstone617=== RUN TestSweepSkipsRowsLockedByPush618=== PAUSE TestSweepSkipsRowsLockedByPush619=== RUN TestRegisterCompletedObjectNeedsPendingRow620=== PAUSE TestRegisterCompletedObjectNeedsPendingRow621=== RUN TestGetExistingObjectsLocksRows622=== PAUSE TestGetExistingObjectsLocksRows623=== RUN TestSweepRechecksPendingAfterLocking624=== PAUSE TestSweepRechecksPendingAfterLocking625=== RUN TestPushWaitsForSweepHoldingRow626=== PAUSE TestPushWaitsForSweepHoldingRow627=== RUN TestCommitRacingPendingCleanupKeepsObjects628=== PAUSE TestCommitRacingPendingCleanupKeepsObjects629=== RUN TestGCEndsOnShutdown630=== PAUSE TestGCEndsOnShutdown631=== RUN TestGCTaskStore_StartNew632=== PAUSE TestGCTaskStore_StartNew633=== RUN TestGCTaskStore_DeduplicateSameParams634=== PAUSE TestGCTaskStore_DeduplicateSameParams635=== RUN TestGCTaskStore_ConflictDifferentParams636=== PAUSE TestGCTaskStore_ConflictDifferentParams637=== RUN TestGCTaskStore_GetEmpty638=== PAUSE TestGCTaskStore_GetEmpty639=== RUN TestGCTaskStore_GetReturnsLatest640=== PAUSE TestGCTaskStore_GetReturnsLatest641=== RUN TestGCTaskStore_CompletedAllowsNewTask642=== PAUSE TestGCTaskStore_CompletedAllowsNewTask643=== RUN TestGCTaskStore_PhaseUpdates644=== PAUSE TestGCTaskStore_PhaseUpdates645=== RUN TestGCTaskStore_Fail646=== PAUSE TestGCTaskStore_Fail647=== RUN TestGracefulShutdownDrainsInflight648=== PAUSE TestGracefulShutdownDrainsInflight649=== RUN TestService_healthCheckHandler650=== PAUSE TestService_healthCheckHandler651=== RUN TestService_readinessHandler652=== PAUSE TestService_readinessHandler653=== RUN TestInitializeBucketNoAwsChunked654=== PAUSE TestInitializeBucketNoAwsChunked655=== RUN TestGenerateLandingPage656=== PAUSE TestGenerateLandingPage657=== RUN TestCacheConfigHandlerMaxNarSize658=== PAUSE TestCacheConfigHandlerMaxNarSize659=== RUN TestCreatePendingClosureRejectsOversizedNAR660=== PAUSE TestCreatePendingClosureRejectsOversizedNAR661=== RUN TestNARDeduplicationMetadataUploadBug662=== PAUSE TestNARDeduplicationMetadataUploadBug663=== RUN TestMetricsInventory664=== PAUSE TestMetricsInventory665=== RUN TestMetricsCommit666=== PAUSE TestMetricsCommit667=== RUN TestService_NativeMTLS668=== PAUSE TestService_NativeMTLS669=== RUN TestServerTLSConfig670=== PAUSE TestServerTLSConfig671=== RUN TestMultipartCleanup672=== PAUSE TestMultipartCleanup673=== RUN TestMultipartUploadAbortedWhenCancelledBeforeRecorded674=== PAUSE TestMultipartUploadAbortedWhenCancelledBeforeRecorded675=== RUN TestPendingCleanupUsesOneCutoff676=== PAUSE TestPendingCleanupUsesOneCutoff677=== RUN TestObjectStatsTrigger678=== PAUSE TestObjectStatsTrigger679=== RUN TestObjectStatsUpdatedOncePerCommit680=== PAUSE TestObjectStatsUpdatedOncePerCommit681=== RUN TestOrphanedObjectsGC682=== PAUSE TestOrphanedObjectsGC683=== RUN TestOrphanedObjectsGCStressTest684=== PAUSE TestOrphanedObjectsGCStressTest685=== RUN TestCreatePin_ReservedPins686=== PAUSE TestCreatePin_ReservedPins687=== RUN TestPresentReportsOnlyClosureRoots688=== PAUSE TestPresentReportsOnlyClosureRoots689=== RUN TestPresentRefreshesOnlyStaleClosures690=== PAUSE TestPresentRefreshesOnlyStaleClosures691=== RUN TestPresentNotReportedWhileGCDeletesClosure692=== PAUSE TestPresentNotReportedWhileGCDeletesClosure693=== RUN TestParseSingleRange694=== PAUSE TestParseSingleRange695=== RUN TestProxyHeadersOnlyTrustedOnSocket6962026/11/06 06:57:39 INFO Starting HTTP server address=127.0.0.1:529116972026/11/06 06:57:39 INFO Starting HTTP server address=proxy.sock6982026/11/06 06:57:39 WARN mTLS auth: subject not in bound subjects subject="CN=someone"6992026/11/06 06:57:39 INFO Shutdown signal received, draining in-flight requests timeout=10s700--- PASS: TestProxyHeadersOnlyTrustedOnSocket (0.17s)701=== RUN TestIsValidCachePath702=== PAUSE TestIsValidCachePath703=== RUN TestReadProxyNarinfo704=== PAUSE TestReadProxyNarinfo705=== RUN TestReadProxyNarinfoAlreadyDecompressed706=== PAUSE TestReadProxyNarinfoAlreadyDecompressed707=== RUN TestReadProxyContentNegotiation708=== PAUSE TestReadProxyContentNegotiation709=== RUN TestReadProxyNarStreaming710=== PAUSE TestReadProxyNarStreaming711=== RUN TestReadProxy404712=== PAUSE TestReadProxy404713=== RUN TestReadProxyInvalidPath714=== PAUSE TestReadProxyInvalidPath715=== RUN TestReadProxyHead716=== PAUSE TestReadProxyHead717=== RUN TestReadProxyOutlastsServerWriteTimeout718=== PAUSE TestReadProxyOutlastsServerWriteTimeout719=== RUN TestReadProxyConditionalGet720=== PAUSE TestReadProxyConditionalGet721=== RUN TestReadProxyRootRedirectsToIndexHTML722=== PAUSE TestReadProxyRootRedirectsToIndexHTML723=== RUN TestReadProxyDisabled724=== PAUSE TestReadProxyDisabled725=== RUN TestReadRedirectNar726=== PAUSE TestReadRedirectNar727=== RUN TestReadRedirectKeepsNarinfoProxied728=== PAUSE TestReadRedirectKeepsNarinfoProxied729=== RUN TestReadProxyRangeRequest730=== PAUSE TestReadProxyRangeRequest731=== RUN TestReadRedirectUsesPublicS3URL732=== PAUSE TestReadRedirectUsesPublicS3URL733=== RUN TestPush_OverlappingRootsStoreOneRowPerKey734=== PAUSE TestPush_OverlappingRootsStoreOneRowPerKey735=== RUN TestPush_CompleteCommitsEveryRoot736=== PAUSE TestPush_CompleteCommitsEveryRoot737=== RUN TestPush_RepeatedRootCommitsOnce738=== PAUSE TestPush_RepeatedRootCommitsOnce739=== RUN TestPush_CompleteWaitsForCleanupOfThePush740=== PAUSE TestPush_CompleteWaitsForCleanupOfThePush741=== RUN TestPush_RootsAreLockedInByteOrder742=== PAUSE TestPush_RootsAreLockedInByteOrder743=== RUN TestPush_SkippedKeySurvivesGCBeforeCommit744=== PAUSE TestPush_SkippedKeySurvivesGCBeforeCommit745=== RUN TestPush_RejectsBadRequests746=== PAUSE TestPush_RejectsBadRequests747=== RUN TestPush_SignsNarinfosOfItsPendingObjects748=== PAUSE TestPush_SignsNarinfosOfItsPendingObjects749=== RUN TestRedundantMultipartUpload750=== PAUSE TestRedundantMultipartUpload751=== RUN TestCompleteMultipartUpload_ErrorButObjectExists752=== PAUSE TestCompleteMultipartUpload_ErrorButObjectExists753=== RUN TestCompletedNarNotReofferedAcrossClosures754=== PAUSE TestCompletedNarNotReofferedAcrossClosures755=== RUN TestPresignedUploadRegisteredBeforeCommit756=== PAUSE TestPresignedUploadRegisteredBeforeCommit757=== RUN TestService_Rustfstest758=== PAUSE TestService_Rustfstest759=== RUN TestParseSize760=== PAUSE TestParseSize761=== RUN TestSkippedUploadsHandler762=== PAUSE TestSkippedUploadsHandler763=== RUN TestSystemdListenerNotActivated764--- PASS: TestSystemdListenerNotActivated (0.00s)765=== RUN TestWatchdogBeatsWhenHealthy766--- PASS: TestWatchdogBeatsWhenHealthy (0.03s)767=== RUN TestWatchdogSkipsWhenUnhealthy7682026/11/06 06:57:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7692026/11/06 06:57:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7702026/11/06 06:57:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7712026/11/06 06:57:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7722026/11/06 06:57:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7732026/11/06 06:57:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7742026/11/06 06:57:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7752026/11/06 06:57:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7762026/11/06 06:57:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"7772026/11/06 06:57:39 WARN watchdog liveness check failed, skipping heartbeat error="context deadline exceeded"778--- PASS: TestWatchdogSkipsWhenUnhealthy (0.20s)779=== RUN TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle780=== PAUSE TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle781=== RUN TestProxyWriteTimeout782=== PAUSE TestProxyWriteTimeout783=== RUN TestPendingClosureWriteTimeout784=== PAUSE TestPendingClosureWriteTimeout785=== RUN TestIsValidUploadKey786=== PAUSE TestIsValidUploadKey787=== RUN TestUploadHandlersRejectInvalidKeys788=== PAUSE TestUploadHandlersRejectInvalidKeys789=== RUN TestUploadHandlersRejectOversizedBody790=== PAUSE TestUploadHandlersRejectOversizedBody791=== RUN TestService_cleanupPendingClosuresHandler792=== PAUSE TestService_cleanupPendingClosuresHandler793=== RUN TestService_createPendingClosureHandler794=== PAUSE TestService_createPendingClosureHandler795=== RUN TestService_verifyS3Integrity796=== PAUSE TestService_verifyS3Integrity797=== RUN TestService_verifyS3ReuploadsStaleNarinfo798=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo799=== RUN TestCompleteMultipartUnregistered800=== PAUSE TestCompleteMultipartUnregistered801=== RUN TestCreatePendingClosure_SmallNARUsesSimplePUT802=== PAUSE TestCreatePendingClosure_SmallNARUsesSimplePUT803=== CONT TestService_AuthMiddleware804=== CONT TestMetricsInventory805=== CONT TestPush_OverlappingRootsStoreOneRowPerKey806=== CONT TestPush_SkippedKeySurvivesGCBeforeCommit807=== CONT TestCreatePendingClosure_SmallNARUsesSimplePUT808=== CONT TestCompleteMultipartUnregistered809=== CONT TestService_verifyS3ReuploadsStaleNarinfo810=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed811=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed812=== RUN TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed813=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed814=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost815=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost816=== RUN TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed817=== CONT TestService_verifyS3Integrity818=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed819=== CONT TestService_cleanupPendingClosuresHandler820=== RUN TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed821=== CONT TestService_createPendingClosureHandler822=== CONT TestUploadHandlersRejectOversizedBody823=== CONT TestUploadHandlersRejectInvalidKeys824=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info825=== CONT TestPendingClosureWriteTimeout826=== CONT TestIsValidUploadKey827=== RUN TestIsValidUploadKey/narinfo828=== PAUSE TestIsValidUploadKey/narinfo829=== RUN TestIsValidUploadKey/nar_zst830=== PAUSE TestIsValidUploadKey/nar_zst831=== RUN TestIsValidUploadKey/nar_xz832=== PAUSE TestIsValidUploadKey/nar_xz833=== RUN TestIsValidUploadKey/nar_plain834=== PAUSE TestIsValidUploadKey/nar_plain835=== RUN TestIsValidUploadKey/listing836=== PAUSE TestIsValidUploadKey/listing837=== RUN TestIsValidUploadKey/build_log838=== PAUSE TestIsValidUploadKey/build_log839=== RUN TestIsValidUploadKey/build_log_home-manager_file840=== PAUSE TestIsValidUploadKey/build_log_home-manager_file841=== RUN TestIsValidUploadKey/build_log_plus_in_name842=== PAUSE TestIsValidUploadKey/build_log_plus_in_name843=== RUN TestIsValidUploadKey/build_log_question_mark844=== PAUSE TestIsValidUploadKey/build_log_question_mark845=== RUN TestIsValidUploadKey/build_log_equals846=== PAUSE TestIsValidUploadKey/build_log_equals847=== RUN TestIsValidUploadKey/realisation848=== PAUSE TestIsValidUploadKey/realisation849=== RUN TestIsValidUploadKey/realisation_plus_in_output850=== PAUSE TestIsValidUploadKey/realisation_plus_in_output851=== RUN TestIsValidUploadKey/nix-cache-info852=== PAUSE TestIsValidUploadKey/nix-cache-info853=== RUN TestIsValidUploadKey/index.html854=== CONT TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle855=== CONT TestSkippedUploadsHandler8562026/11/06 06:57:39 INFO Client skipped oversized paths paths=3 nar_bytes=5000000000857=== CONT TestParseSize858--- PASS: TestParseSize (0.00s)859=== CONT TestPresignedUploadRegisteredBeforeCommit860=== CONT TestService_Rustfstest861=== CONT TestPush_RootsAreLockedInByteOrder862=== CONT TestPush_CompleteWaitsForCleanupOfThePush863=== CONT TestPush_RepeatedRootCommitsOnce864=== CONT TestPush_CompleteCommitsEveryRoot865=== CONT TestReadProxyRangeRequest866--- PASS: TestSkippedUploadsHandler (0.02s)867=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info868=== RUN TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal869=== PAUSE TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal870=== RUN TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key871=== PAUSE TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key872=== RUN TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key873=== PAUSE TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key874=== RUN TestPendingClosureWriteTimeout/empty875=== PAUSE TestPendingClosureWriteTimeout/empty876=== RUN TestPendingClosureWriteTimeout/400_objects877=== PAUSE TestPendingClosureWriteTimeout/400_objects878=== RUN TestPendingClosureWriteTimeout/670k_objects879=== PAUSE TestPendingClosureWriteTimeout/670k_objects880=== RUN TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline881=== PAUSE TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline882=== CONT TestCompleteMultipartUpload_ErrorButObjectExists883=== CONT TestCompletedNarNotReofferedAcrossClosures884=== CONT TestProxyWriteTimeout885=== RUN TestProxyWriteTimeout/narinfo886=== PAUSE TestProxyWriteTimeout/narinfo887=== CONT TestRedundantMultipartUpload888=== PAUSE TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed889=== PAUSE TestIsValidUploadKey/index.html890=== RUN TestIsValidUploadKey/narinfo_key,_nar_type891=== PAUSE TestIsValidUploadKey/narinfo_key,_nar_type892=== RUN TestIsValidUploadKey/nar_key,_narinfo_type893=== PAUSE TestIsValidUploadKey/nar_key,_narinfo_type894=== RUN TestIsValidUploadKey/listing_key,_narinfo_type895=== PAUSE TestIsValidUploadKey/listing_key,_narinfo_type896=== RUN TestIsValidUploadKey/traversal897=== PAUSE TestIsValidUploadKey/traversal898=== RUN TestIsValidUploadKey/traversal_nar899=== PAUSE TestIsValidUploadKey/traversal_nar900=== RUN TestIsValidUploadKey/absolute901=== PAUSE TestIsValidUploadKey/absolute902=== RUN TestIsValidUploadKey/empty_key903=== PAUSE TestIsValidUploadKey/empty_key904=== RUN TestIsValidUploadKey/unknown_type905=== PAUSE TestIsValidUploadKey/unknown_type906=== CONT TestPush_SignsNarinfosOfItsPendingObjects907=== CONT TestPush_RejectsBadRequests908=== RUN TestProxyWriteTimeout/1_GiB_nar909=== PAUSE TestProxyWriteTimeout/1_GiB_nar910=== RUN TestProxyWriteTimeout/10_GiB_nar911=== PAUSE TestProxyWriteTimeout/10_GiB_nar912=== RUN TestProxyWriteTimeout/unknown_size913=== PAUSE TestProxyWriteTimeout/unknown_size914=== CONT TestReadRedirectUsesPublicS3URL915=== RUN TestUploadHandlersRejectOversizedBody/create_pending_closure916=== PAUSE TestUploadHandlersRejectOversizedBody/create_pending_closure917=== RUN TestUploadHandlersRejectOversizedBody/complete_multipart918=== PAUSE TestUploadHandlersRejectOversizedBody/complete_multipart919=== RUN TestUploadHandlersRejectOversizedBody/request_more_parts920=== PAUSE TestUploadHandlersRejectOversizedBody/request_more_parts921=== CONT TestParseSingleRange922=== RUN TestParseSingleRange/none923=== PAUSE TestParseSingleRange/none924=== RUN TestParseSingleRange/unknown_unit925=== PAUSE TestParseSingleRange/unknown_unit926=== RUN TestParseSingleRange/multi-range_ignored927=== PAUSE TestParseSingleRange/multi-range_ignored928=== RUN TestParseSingleRange/malformed_no_dash929=== PAUSE TestParseSingleRange/malformed_no_dash930=== RUN TestParseSingleRange/malformed_both_empty931=== PAUSE TestParseSingleRange/malformed_both_empty932=== RUN TestParseSingleRange/malformed_end_before_start933=== PAUSE TestParseSingleRange/malformed_end_before_start934=== RUN TestParseSingleRange/closed935=== PAUSE TestParseSingleRange/closed936=== RUN TestParseSingleRange/open-ended937=== PAUSE TestParseSingleRange/open-ended938=== RUN TestParseSingleRange/end_clamped_to_size939=== PAUSE TestParseSingleRange/end_clamped_to_size940=== RUN TestParseSingleRange/suffix941=== PAUSE TestParseSingleRange/suffix942=== RUN TestParseSingleRange/suffix_exceeds_size943=== PAUSE TestParseSingleRange/suffix_exceeds_size944=== RUN TestParseSingleRange/single_byte945=== PAUSE TestParseSingleRange/single_byte946=== RUN TestParseSingleRange/start_past_EOF947=== PAUSE TestParseSingleRange/start_past_EOF948=== RUN TestParseSingleRange/start_far_past_EOF949=== PAUSE TestParseSingleRange/start_far_past_EOF950=== CONT TestReadRedirectKeepsNarinfoProxied9512026/11/06 06:57:39 INFO Received push request method=POST path=/api/pushes952--- PASS: TestPush_OverlappingRootsStoreOneRowPerKey (0.69s)953=== CONT TestReadRedirectNar9542026/11/06 06:57:40 INFO Received push request method=POST path=/api/pushes9552026/11/06 06:57:40 INFO Received complete push request method=POST path=/api/pushes/1/complete9562026/11/06 06:57:40 INFO Completed push id=1 objects=4 duration=119.846792ms9572026/11/06 06:57:40 INFO Received push request method=POST path=/api/pushes958--- PASS: TestMetricsInventory (1.20s)959=== CONT TestReadProxyDisabled9602026/11/06 06:57:40 INFO Aborted multipart uploads count=0 kept=09612026/11/06 06:57:40 WARN Force mode enabled - objects will be deleted immediately without grace period9622026/11/06 06:57:40 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=09632026/11/06 06:57:40 INFO Received uploads request method=POST path=/api/pending_closures9642026/11/06 06:57:40 INFO Vacuumed table table=pending_closures9652026/11/06 06:57:40 INFO Vacuumed table table=pending_objects9662026/11/06 06:57:40 INFO Vacuumed table table=multipart_uploads9672026/11/06 06:57:40 INFO Vacuumed table table=closures9682026/11/06 06:57:40 INFO Vacuumed table table=objects9692026/11/06 06:57:40 INFO Received complete push request method=POST path=/api/pushes/2/complete9702026/11/06 06:57:40 INFO Completed push id=2 objects=4 duration=9.435583ms971--- PASS: TestCreatePendingClosure_SmallNARUsesSimplePUT (1.44s)972--- PASS: TestPush_SkippedKeySurvivesGCBeforeCommit (1.44s)973=== CONT TestReadProxyRootRedirectsToIndexHTML974=== CONT TestReadProxyConditionalGet9752026/11/06 06:57:41 INFO Received uploads request method=POST path=/api/pending_closures9762026/11/06 06:57:41 WARN Authentication failed token_preview=wrongtoken token_length=10 reason="static API token mismatch"977--- PASS: TestService_AuthMiddleware (2.06s)978=== CONT TestReadProxyOutlastsServerWriteTimeout9792026/11/06 06:57:41 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9802026/11/06 06:57:41 ERROR Failed to get multipart upload error="no rows in result set" upload_id=does-not-exist object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst981--- PASS: TestCompleteMultipartUnregistered (2.36s)982=== CONT TestReadProxyHead9832026/11/06 06:57:42 INFO Received uploads request method=POST path=/api/pending_closures9842026/11/06 06:57:42 INFO Received uploads request method=POST path=/api/pending_closures9852026/11/06 06:57:42 INFO Received uploads request method=POST path=/api/pending_closures9862026/11/06 06:57:42 INFO Received uploads request method=POST path=/api/pending_closures9872026/11/06 06:57:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9882026/11/06 06:57:42 INFO Received push request method=POST path=/api/pushes9892026/11/06 06:57:42 INFO Received complete multipart upload request method=POST path=/api/multipart/complete9902026/11/06 06:57:42 WARN CompleteMultipartUpload errored but object exists; treating as success error="The specified key does not exist." object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LmExYzk5MzI4LWU3YzMtNDYzZS05MzZjLTJlNmJiYmQ2ZjcwM3gxNzkzOTQ4MjYyMzcwMTU2MDAw9912026/11/06 06:57:42 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LjlmOWQ5M2Y0LWQ3ZTAtNGYxOC05ZjQwLTdiMjFlMGU1NTljN3gxNzkzOTQ4MjYxMTEwMzg1MDAw parts=109922026/11/06 06:57:42 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete9932026/11/06 06:57:42 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0300000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LmExYzk5MzI4LWU3YzMtNDYzZS05MzZjLTJlNmJiYmQ2ZjcwM3gxNzkzOTQ4MjYyMzcwMTU2MDAw parts=19942026/11/06 06:57:42 INFO Completed upload id=1 objects=2 duration=33.669125ms995--- PASS: TestCompleteMultipartUpload_ErrorButObjectExists (3.34s)996=== CONT TestReadProxyInvalidPath9972026/11/06 06:57:42 INFO Received complete push request method=POST path=/api/pushes/1/complete9982026/11/06 06:57:42 INFO Received uploads request method=POST path=/api/pending_closures9992026/11/06 06:57:42 INFO Received uploads request method=POST path=/api/pending_closures10002026/11/06 06:57:42 INFO Object in database but missing from S3 key=dadb44fdadb44fdadb44fdadb44f0000.narinfo10012026/11/06 06:57:42 WARN Found objects in DB but missing from S3, will re-upload count=11002--- PASS: TestService_verifyS3Integrity (3.44s)1003=== CONT TestGCSweepSkipsPendingObjects10042026/11/06 06:57:42 INFO Completed push id=1 objects=6 duration=25.855875ms1005--- PASS: TestPush_CompleteCommitsEveryRoot (3.39s)1006=== CONT TestReadProxy40410072026/11/06 06:57:43 INFO Received cleanup request method=DELETE path=/api/pending_closures10082026/11/06 06:57:43 INFO Aborted multipart uploads count=0 kept=010092026/11/06 06:57:43 INFO Received uploads request method=POST path=/api/pending_closures10102026/11/06 06:57:43 INFO Received cleanup request method=DELETE path=/api/pending_closures10112026/11/06 06:57:43 INFO Aborted multipart uploads count=1 kept=010122026/11/06 06:57:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10132026-11-06 06:57:43.140 UTC [77911] ERROR: Closure does not exist: id=110142026-11-06 06:57:43.140 UTC [77911] CONTEXT: PL/pgSQL function commit_pending_closure(bigint) line 13 at RAISE10152026-11-06 06:57:43.140 UTC [77911] STATEMENT: -- name: CommitPendingClosure :one1016 SELECT commit_pending_closure($1::bigint)::bigint1017 1018--- PASS: TestService_cleanupPendingClosuresHandler (3.73s)1019=== CONT TestReadProxyNarStreaming10202026/11/06 06:57:43 INFO Received push request method=POST path=/api/pushes10212026/11/06 06:57:43 INFO Received push request method=POST path=/api/pushes10222026/11/06 06:57:43 INFO Received complete multipart upload request method=POST path=/api/multipart/complete10232026/11/06 06:57:43 INFO Received complete push request method=POST path=/api/pushes/1/complete10242026/11/06 06:57:43 INFO Completed push id=1 objects=4 duration=28.550958ms1025--- PASS: TestPush_RepeatedRootCommitsOnce (4.16s)1026=== CONT TestReadProxyContentNegotiation10272026/11/06 06:57:43 INFO Completed multipart upload object_key=nar/0000000000000000000000000000000000000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LmRjZDcyNTQxLWQwZGYtNGQ3Ny1hNDQ3LTY2ODVhZjA3YjE4ZHgxNzkzOTQ4MjYyMDMzNzU2MDAw parts=1010282026/11/06 06:57:43 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete10292026/11/06 06:57:43 INFO Completed upload id=1 objects=2 duration=17.107834ms10302026/11/06 06:57:43 INFO Received get closure request method=GET path=/api/closures/0000000000000000000000000000000010312026/11/06 06:57:43 INFO Received uploads request method=POST path=/api/pending_closures10322026-11-06 06:57:43.661 UTC [77945] ERROR: Push does not exist: id=110332026-11-06 06:57:43.661 UTC [77945] CONTEXT: PL/pgSQL function commit_push(bigint) line 11 at RAISE10342026-11-06 06:57:43.661 UTC [77945] STATEMENT: SELECT commit_push($1)10352026/11/06 06:57:43 INFO Starting cleanup of old closures method=DELETE path=/api/closures1036--- PASS: TestPush_CompleteWaitsForCleanupOfThePush (4.20s)1037=== CONT TestReadProxyNarinfoAlreadyDecompressed10382026/11/06 06:57:43 INFO Aborted multipart uploads count=0 kept=010392026/11/06 06:57:43 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=010402026/11/06 06:57:43 INFO Vacuumed table table=pending_closures10412026/11/06 06:57:43 INFO Received uploads request method=POST path=/api/pending_closures10422026/11/06 06:57:43 INFO Vacuumed table table=pending_objects10432026/11/06 06:57:43 INFO Vacuumed table table=multipart_uploads10442026/11/06 06:57:43 INFO Vacuumed table table=closures10452026/11/06 06:57:43 INFO Vacuumed table table=objects10462026/11/06 06:57:43 INFO Received get closure request method=GET path=/api/closures/000000000000000000000000000000001047--- PASS: TestService_createPendingClosureHandler (4.36s)1048=== CONT TestReadProxyNarinfo10492026/11/06 06:57:43 INFO Registered completed upload object_key=nar/jjjjjjjjjjjjjjjjjjjjjjjjjjjjjj0100000000000000000000.nar.zst10502026/11/06 06:57:43 INFO Received uploads request method=POST path=/api/pending_closures1051--- PASS: TestPresignedUploadRegisteredBeforeCommit (4.34s)1052=== CONT TestIsValidCachePath1053=== RUN TestIsValidCachePath/narinfo1054=== PAUSE TestIsValidCachePath/narinfo1055=== RUN TestIsValidCachePath/narinfo_all_nix_base32_chars1056=== PAUSE TestIsValidCachePath/narinfo_all_nix_base32_chars1057=== RUN TestIsValidCachePath/nar_zst1058=== PAUSE TestIsValidCachePath/nar_zst1059=== RUN TestIsValidCachePath/nar_xz1060=== PAUSE TestIsValidCachePath/nar_xz1061=== RUN TestIsValidCachePath/nar_bz21062=== PAUSE TestIsValidCachePath/nar_bz21063=== RUN TestIsValidCachePath/nar_uncompressed1064=== PAUSE TestIsValidCachePath/nar_uncompressed1065=== RUN TestIsValidCachePath/ls1066=== PAUSE TestIsValidCachePath/ls1067=== RUN TestIsValidCachePath/log1068=== PAUSE TestIsValidCachePath/log1069=== RUN TestIsValidCachePath/realisation1070=== PAUSE TestIsValidCachePath/realisation1071=== RUN TestIsValidCachePath/nix-cache-info1072=== PAUSE TestIsValidCachePath/nix-cache-info1073=== RUN TestIsValidCachePath/index.html1074=== PAUSE TestIsValidCachePath/index.html1075=== RUN TestIsValidCachePath/traversal_parent1076=== PAUSE TestIsValidCachePath/traversal_parent1077=== RUN TestIsValidCachePath/traversal_in_middle1078=== PAUSE TestIsValidCachePath/traversal_in_middle1079=== RUN TestIsValidCachePath/invalid_char_e1080=== PAUSE TestIsValidCachePath/invalid_char_e1081=== RUN TestIsValidCachePath/invalid_char_u1082=== PAUSE TestIsValidCachePath/invalid_char_u1083=== RUN TestIsValidCachePath/random_path1084=== PAUSE TestIsValidCachePath/random_path1085=== RUN TestIsValidCachePath/empty1086=== PAUSE TestIsValidCachePath/empty1087=== RUN TestIsValidCachePath/leading_slash1088=== PAUSE TestIsValidCachePath/leading_slash1089=== RUN TestIsValidCachePath/wrong_extension1090=== PAUSE TestIsValidCachePath/wrong_extension1091=== RUN TestIsValidCachePath/short_hash1092=== PAUSE TestIsValidCachePath/short_hash1093=== CONT TestNARDeduplicationMetadataUploadBug10942026/11/06 06:57:43 INFO Received push request method=POST path=/api/pushes10952026-11-06 06:57:44.075 UTC [77959] ERROR: could not obtain lock on row in relation "closures"10962026-11-06 06:57:44.075 UTC [77959] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10972026-11-06 06:57:44.078 UTC [77959] ERROR: could not obtain lock on row in relation "closures"10982026-11-06 06:57:44.078 UTC [77959] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT10992026-11-06 06:57:44.080 UTC [77959] ERROR: could not obtain lock on row in relation "closures"11002026-11-06 06:57:44.080 UTC [77959] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11012026-11-06 06:57:44.080 UTC [77959] ERROR: could not obtain lock on row in relation "closures"11022026-11-06 06:57:44.080 UTC [77959] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT11032026-11-06 06:57:44.080 UTC [77959] ERROR: could not obtain lock on row in relation "closures"11042026-11-06 06:57:44.080 UTC [77959] STATEMENT: SELECT 1 FROM closures WHERE key = $1 FOR UPDATE NOWAIT1105--- PASS: TestPush_RootsAreLockedInByteOrder (4.63s)1106=== CONT TestGCTaskStore_DeduplicateSameParams1107--- PASS: TestGCTaskStore_DeduplicateSameParams (0.00s)1108=== CONT TestCreatePendingClosureRejectsOversizedNAR11092026/11/06 06:57:44 INFO Received uploads request method=POST path=/api/pending_closures1110--- PASS: TestCreatePendingClosureRejectsOversizedNAR (0.00s)1111=== CONT TestCacheConfigHandlerMaxNarSize1112--- PASS: TestCacheConfigHandlerMaxNarSize (0.00s)1113=== CONT TestGenerateLandingPage1114--- PASS: TestGenerateLandingPage (0.00s)1115=== CONT TestGCTaskStore_StartNew1116--- PASS: TestGCTaskStore_StartNew (0.00s)1117=== CONT TestInitializeBucketNoAwsChunked1118=== RUN TestPush_RejectsBadRequests/no_roots1119=== PAUSE TestPush_RejectsBadRequests/no_roots1120=== RUN TestPush_RejectsBadRequests/no_objects1121=== PAUSE TestPush_RejectsBadRequests/no_objects1122=== RUN TestPush_RejectsBadRequests/bad_root1123=== PAUSE TestPush_RejectsBadRequests/bad_root1124=== RUN TestPush_RejectsBadRequests/root_not_in_objects1125=== PAUSE TestPush_RejectsBadRequests/root_not_in_objects1126=== CONT TestService_readinessHandler1127--- PASS: TestReadProxyRangeRequest (4.94s)1128=== CONT TestService_healthCheckHandler11292026/11/06 06:57:44 INFO Received uploads request method=POST path=/api/pending_closures11302026/11/06 06:57:44 INFO Received uploads request method=POST path=/api/pending_closures11312026/11/06 06:57:44 INFO Received push request method=POST path=/api/pushes11322026/11/06 06:57:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11332026/11/06 06:57:44 INFO Signed narinfos id=1 count=111342026/11/06 06:57:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11352026/11/06 06:57:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11362026/11/06 06:57:44 ERROR Failed to sign narinfos signer="index 1" error="signing key cannot be nil"11372026/11/06 06:57:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11382026/11/06 06:57:44 ERROR Failed to sign narinfos signer=niks3-test-1 error="signer failed"11392026/11/06 06:57:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11402026/11/06 06:57:44 ERROR Signer returned unexpected signature count signer=niks3-test-1 got=0 want=111412026/11/06 06:57:44 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign11422026/11/06 06:57:44 ERROR Signer returned unexpected object key signer=niks3-test-1 object_key=unexpected.narinfo1143--- PASS: TestPush_SignsNarinfosOfItsPendingObjects (5.51s)1144=== CONT TestGracefulShutdownDrainsInflight11452026/11/06 06:57:45 INFO Starting HTTP server address=127.0.0.1:5298711462026/11/06 06:57:45 INFO Shutdown signal received, draining in-flight requests timeout=10s1147--- PASS: TestGracefulShutdownDrainsInflight (0.07s)1148=== CONT TestGCTaskStore_Fail1149--- PASS: TestGCTaskStore_Fail (0.00s)1150=== CONT TestGCEndsOnShutdown1151=== RUN TestGCEndsOnShutdown/before_the_run1152=== PAUSE TestGCEndsOnShutdown/before_the_run1153=== RUN TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1154=== PAUSE TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1155=== RUN TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1156=== PAUSE TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark1157=== CONT TestGCTaskStore_PhaseUpdates1158--- PASS: TestGCTaskStore_PhaseUpdates (0.00s)1159=== CONT TestCommitRacingPendingCleanupKeepsObjects1160--- PASS: TestReadRedirectUsesPublicS3URL (5.73s)1161=== CONT TestGCTaskStore_CompletedAllowsNewTask1162--- PASS: TestGCTaskStore_CompletedAllowsNewTask (0.00s)1163=== CONT TestPushWaitsForSweepHoldingRow11642026/11/06 06:57:45 INFO Received uploads request method=POST path=/api/pending_closures1165--- PASS: TestService_Rustfstest (6.24s)1166=== CONT TestGCTaskStore_GetReturnsLatest1167--- PASS: TestGCTaskStore_GetReturnsLatest (0.00s)1168=== CONT TestSweepRechecksPendingAfterLocking11692026/11/06 06:57:45 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1170--- PASS: TestReadRedirectKeepsNarinfoProxied (6.55s)1171=== CONT TestGCTaskStore_GetEmpty1172--- PASS: TestGCTaskStore_GetEmpty (0.00s)1173=== CONT TestGetExistingObjectsLocksRows11742026/11/06 06:57:46 INFO Received uploads request method=POST path=/api/pending_closures11752026/11/06 06:57:46 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11762026/11/06 06:57:46 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0100000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LmUyYmVlYTQ1LWJkZTItNDBkZi1hOTVjLWMzZmU3NzM1OGY3OXgxNzkzOTQ4MjY0NjEwNTg1MDAw parts=1211772026/11/06 06:57:46 INFO Received uploads request method=POST path=/api/pending_closures11782026/11/06 06:57:46 INFO Received uploads request method=POST path=/api/pending_closures1179--- PASS: TestReadProxyConditionalGet (5.79s)1180=== CONT TestGCTaskStore_ConflictDifferentParams1181--- PASS: TestGCTaskStore_ConflictDifferentParams (0.00s)1182=== CONT TestRegisterCompletedObjectNeedsPendingRow1183--- PASS: TestReadProxyRootRedirectsToIndexHTML (6.11s)1184=== CONT TestSweepSkipsRowsLockedByPush1185--- PASS: TestReadProxyDisabled (6.64s)1186=== CONT TestCreatePendingClosureVerifyS3FailureReleasesConnection1187--- PASS: TestReadRedirectNar (7.57s)1188=== CONT TestGCSweepDeliversEachKeyOnce1189--- PASS: TestReadProxyHead (6.46s)1190=== CONT TestFailedS3DeleteKeepsTombstone11912026/11/06 06:57:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete11922026/11/06 06:57:48 INFO Completed multipart upload object_key=nar/hhhhhhhhhhhhhhhhhhhhhhhhhhhhhh0100000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LjM5MGUzOTAwLThkNzktNDZjYS1hMmU1LTUyNWYzODVjNDg0ZXgxNzkzOTQ4MjY2MzI4NTcxMDAw parts=1211932026/11/06 06:57:48 INFO Received uploads request method=POST path=/api/pending_closures1194--- PASS: TestCompletedNarNotReofferedAcrossClosures (8.86s)1195=== CONT TestTombstonedObjectOfferedWithoutWaiting11962026/11/06 06:57:48 INFO Received complete multipart upload request method=POST path=/api/multipart/complete1197--- PASS: TestReadProxyInvalidPath (5.66s)1198=== CONT TestForceGCDuringPushOffersSweptObject1199=== RUN TestForceGCDuringPushOffersSweptObject/before_pending_rows1200=== PAUSE TestForceGCDuringPushOffersSweptObject/before_pending_rows1201=== RUN TestForceGCDuringPushOffersSweptObject/after_presence_check1202=== PAUSE TestForceGCDuringPushOffersSweptObject/after_presence_check1203=== CONT TestObjectStatsUpdatedOncePerCommit12042026/11/06 06:57:48 WARN Failed to abort redundant multipart upload, keeping its row object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LjJhZTQzNDJmLTg3ZjMtNGU1Zi1iNDM5LWI5YzI0NmY2ODRiNngxNzkzOTQ4MjY2NDgwNTAxMDAw error="Get \"http://127.0.0.1:1/bucket21/?location=\": dial tcp 127.0.0.1:1: connect: connection refused"12052026/11/06 06:57:48 INFO Completed multipart upload object_key=nar/gggggggggggggggggggggggggggggg0200000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LjQ4NDhkOTk1LWI4YWMtNDg0Ny1hYWI5LTE5MTUzMWJhODcwM3gxNzkzOTQ4MjY2NDM0MTk3MDAw parts=1212062026/11/06 06:57:48 INFO Received cleanup request method=DELETE path=/api/pending_closures12072026/11/06 06:57:48 INFO Aborted multipart uploads count=1 kept=01208--- PASS: TestRedundantMultipartUpload (9.05s)1209=== CONT TestPresentNotReportedWhileGCDeletesClosure1210=== RUN TestPresentNotReportedWhileGCDeletesClosure/stale1211=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/stale1212=== RUN TestPresentNotReportedWhileGCDeletesClosure/fresh1213=== PAUSE TestPresentNotReportedWhileGCDeletesClosure/fresh1214=== CONT TestPresentRefreshesOnlyStaleClosures12152026/11/06 06:57:49 INFO Received uploads request method=POST path=/api/pending_closures12162026/11/06 06:57:49 INFO Aborted multipart uploads count=0 kept=012172026/11/06 06:57:49 WARN Force mode enabled - objects will be deleted immediately without grace period12182026/11/06 06:57: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=01219--- PASS: TestReadProxy404 (6.39s)1220=== CONT TestPresentReportsOnlyClosureRoots12212026/11/06 06:57:49 INFO Vacuumed table table=pending_closures12222026/11/06 06:57:49 INFO Vacuumed table table=pending_objects12232026/11/06 06:57:49 INFO Vacuumed table table=multipart_uploads12242026/11/06 06:57:49 INFO Vacuumed table table=closures12252026/11/06 06:57:49 INFO Vacuumed table table=objects1226--- PASS: TestGCSweepSkipsPendingObjects (6.50s)1227=== CONT TestCreatePin_ReservedPins12282026/11/06 06:57:49 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53067/oidc1229--- PASS: TestReadProxyNarStreaming (6.30s)1230=== CONT TestOrphanedObjectsGCStressTest12312026/11/06 06:57:49 ERROR Failed to decode narinfo key=3hcdxyjf9yiq7qf3i4548drb6sjmwa1v.narinfo limit=16777216 error=<nil>1232--- PASS: TestReadProxyNarinfo (5.97s)1233=== CONT TestOrphanedObjectsGC1234--- PASS: TestReadProxyContentNegotiation (6.45s)1235=== CONT TestMultipartCleanup1236--- PASS: TestReadProxyNarinfoAlreadyDecompressed (6.59s)1237=== CONT TestObjectStatsTrigger12382026/11/06 06:57:50 WARN Rate limiter enabled after throttle name=s3-test rate=512392026/11/06 06:57:50 WARN S3 rate limit hit operation="complete multipart upload" error="Please reduce your request rate."1240=== NAME TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle1241 throttle_test.go:213: Proxy stats: total=13, throttled=10, completeMultipart=101242 throttle_test.go:215: Rate limiter: enabled=true, rate=5.001243--- PASS: TestCompleteMultipartUploadHandler_RateLimitTriggersThrottle (11.03s)1244=== CONT TestPendingCleanupUsesOneCutoff1245--- PASS: TestInitializeBucketNoAwsChunked (6.73s)1246=== CONT TestMultipartUploadAbortedWhenCancelledBeforeRecorded1247=== NAME TestNARDeduplicationMetadataUploadBug1248 metadata_upload_test.go:48: First store path: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestNARDeduplicationMetadataUploadBug2945512356/001/store/6pphv81aij2pg4m1g78a1lsp27s8z8k4-file1.txt12492026/11/06 06:57:50 INFO Received push request method=POST path=/api/pushes12502026/11/06 06:57:50 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)12512026/11/06 06:57:51 INFO Uploading 6pphv81aij2pg4m1g78a1lsp27s8z8k4-file1.txt (160B)12522026/11/06 06:57:51 WARN Failed to register uploaded object key=6pphv81aij2pg4m1g78a1lsp27s8z8k4.ls error="server returned 404: 404 page not found\n"12532026/11/06 06:57:51 WARN Failed to register uploaded object key=nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst error="server returned 404: 404 page not found\n"12542026/11/06 06:57:51 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign12552026/11/06 06:57:51 INFO Signed narinfos id=1 count=112562026/11/06 06:57:51 INFO Uploading 1 narinfos12572026/11/06 06:57:51 WARN readiness check failed error="closed pool"1258--- PASS: TestService_readinessHandler (6.88s)1259=== CONT TestLeadIncumbentAnnouncesAtOnce12602026/11/06 06:57:51 INFO Received complete push request method=POST path=/api/pushes/1/complete12612026/11/06 06:57:51 WARN Failed to register uploaded object key=6pphv81aij2pg4m1g78a1lsp27s8z8k4.narinfo error="server returned 404: 404 page not found\n"12622026/11/06 06:57:51 INFO Completed push id=1 objects=3 duration=22.468416ms12632026/11/06 06:57:51 INFO Upload complete. (215ms)1264=== NAME TestNARDeduplicationMetadataUploadBug1265 metadata_upload_test.go:54: Retrieved narinfo from S3:1266 StorePath: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestNARDeduplicationMetadataUploadBug2945512356/001/store/6pphv81aij2pg4m1g78a1lsp27s8z8k4-file1.txt1267 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1268 Compression: zstd1269 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1270 NarSize: 1601271 References: 1272 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1273 metadata_upload_test.go:55: Retrieved .ls file from S3 (compressed size: 77 bytes)1274 metadata_upload_test.go:55: Decompressed .ls content (64 bytes):1275 {"version":1,"root":{"type":"regular","size":44,"narOffset":96}}1276 metadata_upload_test.go:64: Second store path (same content): /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestNARDeduplicationMetadataUploadBug2945512356/001/store/38yijv4m57j99xxwwa0chfvh1bcz39ms-file2.txt12772026/11/06 06:57:51 INFO Received push request method=POST path=/api/pushes12782026/11/06 06:57:51 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)1279--- PASS: TestService_healthCheckHandler (6.88s)1280=== CONT TestDeduplicatedObjectsRecordedAsPending12812026/11/06 06:57:51 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign12822026/11/06 06:57:51 WARN Failed to register uploaded object key=38yijv4m57j99xxwwa0chfvh1bcz39ms.ls error="server returned 404: 404 page not found\n"12832026/11/06 06:57:51 INFO Signed narinfos id=2 count=112842026/11/06 06:57:51 INFO Uploading 1 narinfos12852026/11/06 06:57:51 INFO Received complete push request method=POST path=/api/pushes/2/complete12862026/11/06 06:57:51 WARN Failed to register uploaded object key=38yijv4m57j99xxwwa0chfvh1bcz39ms.narinfo error="server returned 404: 404 page not found\n"12872026/11/06 06:57:51 INFO Completed push id=2 objects=3 duration=1.67525ms12882026/11/06 06:57:51 INFO Upload complete. (121ms)1289=== NAME TestNARDeduplicationMetadataUploadBug1290 metadata_upload_test.go:76: Retrieved narinfo from S3:1291 StorePath: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestNARDeduplicationMetadataUploadBug2945512356/001/store/38yijv4m57j99xxwwa0chfvh1bcz39ms-file2.txt1292 URL: nar/1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf.nar.zst1293 Compression: zstd1294 NarHash: sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1295 NarSize: 1601296 References: 1297 CA: fixed:r:sha256:1byf36hhc5sn8lvwqfkjh3ybgn76slmx8naakslrypxs6mna71rf1298 metadata_upload_test.go:77: Retrieved .ls file from S3 (compressed size: 62 bytes)1299 metadata_upload_test.go:77: Decompressed .ls content (49 bytes):1300 {"version":1,"root":{"type":"regular","size":44}}1301--- PASS: TestNARDeduplicationMetadataUploadBug (7.56s)1302=== CONT TestPushDedupSurvivesConcurrentGC13032026/11/06 06:57:51 INFO Aborted multipart uploads count=0 kept=013042026/11/06 06:57:51 WARN Force mode enabled - objects will be deleted immediately without grace period13052026/11/06 06:57:51 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=013062026/11/06 06:57:51 INFO Vacuumed table table=pending_closures13072026/11/06 06:57:51 INFO Vacuumed table table=pending_objects13082026/11/06 06:57:51 INFO Vacuumed table table=multipart_uploads13092026/11/06 06:57:51 INFO Vacuumed table table=closures13102026/11/06 06:57:51 INFO Vacuumed table table=objects13112026/11/06 06:57:51 INFO Received uploads request method=POST path=/api/pending_closures1312--- PASS: TestCommitRacingPendingCleanupKeepsObjects (6.69s)1313=== CONT TestPinProtectsFromGC13142026/11/06 06:57:52 INFO Aborted multipart uploads count=0 kept=013152026/11/06 06:57:52 WARN Force mode enabled - objects will be deleted immediately without grace period13162026/11/06 06:57:52 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=013172026/11/06 06:57:52 INFO Vacuumed table table=pending_closures13182026/11/06 06:57:52 INFO Vacuumed table table=pending_objects13192026/11/06 06:57:52 INFO Vacuumed table table=multipart_uploads13202026/11/06 06:57:52 INFO Vacuumed table table=closures13212026/11/06 06:57:52 INFO Vacuumed table table=objects1322--- PASS: TestSweepRechecksPendingAfterLocking (6.45s)1323=== CONT TestGCMetrics1324--- PASS: TestGetExistingObjectsLocksRows (6.14s)1325=== CONT TestGCBugBareHashReferences1326--- PASS: TestReadProxyOutlastsServerWriteTimeout (10.74s)1327=== CONT TestGCAdvisoryLockBlocksConcurrentRun1328--- PASS: TestPushWaitsForSweepHoldingRow (7.04s)1329=== CONT TestLeadEndsOnShutdown1330--- PASS: TestRegisterCompletedObjectNeedsPendingRow (5.72s)1331=== CONT TestLeadElectsOneAndHandsOver13322026/11/06 06:57:52 INFO Aborted multipart uploads count=0 kept=013332026/11/06 06:57:52 WARN Force mode enabled - objects will be deleted immediately without grace period13342026/11/06 06:57:52 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=013352026/11/06 06:57:52 INFO Vacuumed table table=pending_closures13362026/11/06 06:57:52 INFO Vacuumed table table=pending_objects13372026/11/06 06:57:52 INFO Vacuumed table table=multipart_uploads13382026/11/06 06:57:52 INFO Vacuumed table table=closures13392026/11/06 06:57:52 INFO Vacuumed table table=objects13402026/11/06 06:57:52 INFO Aborted multipart uploads count=0 kept=013412026/11/06 06:57:52 WARN Force mode enabled - objects will be deleted immediately without grace period13422026/11/06 06:57:52 INFO Received uploads request method=POST path=/api/pending_closures13432026/11/06 06:57:52 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=013442026/11/06 06:57:52 INFO Vacuumed table table=pending_closures13452026/11/06 06:57:52 INFO Vacuumed table table=pending_objects13462026/11/06 06:57:52 INFO Vacuumed table table=multipart_uploads13472026/11/06 06:57:52 INFO Vacuumed table table=closures13482026/11/06 06:57:52 INFO Vacuumed table table=objects1349--- PASS: TestSweepSkipsRowsLockedByPush (5.99s)1350=== CONT TestConnectWaitsForAPeerMigration1351--- PASS: TestCreatePendingClosureVerifyS3FailureReleasesConnection (5.76s)1352=== CONT TestResolveDBConnectionString1353=== RUN TestResolveDBConnectionString/flag_wins1354=== PAUSE TestResolveDBConnectionString/flag_wins1355=== RUN TestResolveDBConnectionString/file_when_flag_empty1356=== PAUSE TestResolveDBConnectionString/file_when_flag_empty1357=== RUN TestResolveDBConnectionString/missing_file_is_an_error1358=== PAUSE TestResolveDBConnectionString/missing_file_is_an_error1359=== RUN TestResolveDBConnectionString/PGHOST_allows_empty1360=== PAUSE TestResolveDBConnectionString/PGHOST_allows_empty1361=== RUN TestResolveDBConnectionString/nothing_configured1362=== PAUSE TestResolveDBConnectionString/nothing_configured1363=== CONT TestConcurrentCommitsSharingObjectsDoNotDeadlock13642026/11/06 06:57:53 INFO Aborted multipart uploads count=0 kept=013652026/11/06 06:57:53 WARN Force mode enabled - objects will be deleted immediately without grace period13662026/11/06 06:57:53 INFO Received uploads request method=POST path=/api/pending_closures13672026/11/06 06:57:53 INFO Aborted multipart uploads count=0 kept=013682026/11/06 06:57:53 WARN Force mode enabled - objects will be deleted immediately without grace period13692026/11/06 06:57:53 ERROR failed to remove object object=nar/dddddddddddddddddddddddddddddddddddddddddddddddddddd.nar.zst error="Access Denied."13702026/11/06 06:57:53 ERROR failed to remove object object=dddddddddddddddddddddddddddddddd.narinfo error="Access Denied."1371--- PASS: TestFailedS3DeleteKeepsTombstone (5.45s)1372=== CONT TestDeleteClosuresRacingPins13732026/11/06 06:57:53 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=013742026/11/06 06:57:53 INFO Vacuumed table table=pending_closures13752026/11/06 06:57:53 INFO Vacuumed table table=pending_objects13762026/11/06 06:57:53 INFO Received uploads request method=POST path=/api/pending_closures13772026/11/06 06:57:53 INFO Vacuumed table table=multipart_uploads13782026/11/06 06:57:53 INFO Vacuumed table table=closures13792026/11/06 06:57:53 INFO Vacuumed table table=objects1380--- PASS: TestGCSweepDeliversEachKeyOnce (6.09s)1381=== CONT TestClientFallsBackToClosures1382--- PASS: TestTombstonedObjectOfferedWithoutWaiting (5.42s)1383=== CONT TestClientPushesUseOnePush1384--- PASS: TestPresentRefreshesOnlyStaleClosures (5.44s)1385=== CONT TestClientMultipleUploads1386--- PASS: TestObjectStatsUpdatedOncePerCommit (5.74s)1387=== CONT TestCacheStatsHandler1388--- PASS: TestPresentReportsOnlyClosureRoots (5.09s)1389=== CONT TestClientIntegration13902026/11/06 06:57:54 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13912026/11/06 06:57:54 WARN Refused reserved pin name=worker-x86_64-linux13922026/11/06 06:57:54 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux13932026/11/06 06:57:54 INFO Received create pin request method=POST path=/api/pins/my-app13942026/11/06 06:57:54 INFO Received create pin request method=POST path=/api/pins/worker-x86_64-linux1395--- PASS: TestCreatePin_ReservedPins (5.14s)1396=== CONT TestClientErrorHandling1397=== RUN TestClientErrorHandling/InvalidStorePath1398=== PAUSE TestClientErrorHandling/InvalidStorePath1399=== RUN TestClientErrorHandling/InvalidAuthToken1400=== PAUSE TestClientErrorHandling/InvalidAuthToken1401=== RUN TestClientErrorHandling/ServerNotAvailable1402=== PAUSE TestClientErrorHandling/ServerNotAvailable1403=== CONT TestClientCADerivations14042026/11/06 06:57:55 INFO Received uploads request method=POST path=/api/pending_closures14052026/11/06 06:57:55 INFO Received cleanup request method=DELETE path=/api/pending_closures14062026/11/06 06:57:55 WARN Failed to abort upload, keeping its closure key=nar/dadb44fdadb44fdadb44fdadb44f000000000000000000000000.nar.zst error="Get \"http://127.0.0.1:1/bucket61/?location=\": dial tcp 127.0.0.1:1: connect: connection refused" code=""14072026/11/06 06:57:55 INFO Aborted multipart uploads count=0 kept=114082026/11/06 06:57:55 INFO Received cleanup request method=DELETE path=/api/pending_closures14092026/11/06 06:57:55 INFO Aborted multipart uploads count=1 kept=01410--- PASS: TestMultipartCleanup (5.45s)1411=== CONT TestService_AuthMiddleware_OIDC1412--- PASS: TestObjectStatsTrigger (5.40s)1413=== CONT TestClientSharedPathCommittedMidPush14142026/11/06 06:57:55 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53152/oidc14152026/11/06 06:57:55 INFO Received uploads request method=POST path=/api/pending_closures14162026/11/06 06:57:56 INFO Received uploads request method=POST path=/api/pending_closures14172026/11/06 06:57:56 INFO Received cleanup request method=DELETE path=/api/pending_closures14182026/11/06 06:57:56 INFO Received uploads request method=POST path=/api/pending_closures1419--- PASS: TestMultipartUploadAbortedWhenCancelledBeforeRecorded (5.57s)1420=== CONT TestClientWithDependencies14212026/11/06 06:57:56 INFO lead: acquired remote=192.0.2.1:123414222026/11/06 06:57:56 INFO lead: released remote=192.0.2.1:12341423--- PASS: TestLeadIncumbentAnnouncesAtOnce (5.59s)1424=== CONT TestCacheConfigHandler1425=== RUN TestCacheConfigHandler/full_config,_no_issuer1426=== PAUSE TestCacheConfigHandler/full_config,_no_issuer1427=== RUN TestCacheConfigHandler/no_cache_url_configured1428=== PAUSE TestCacheConfigHandler/no_cache_url_configured1429=== RUN TestCacheConfigHandler/no_signing_keys1430=== PAUSE TestCacheConfigHandler/no_signing_keys1431=== RUN TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1432=== PAUSE TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator1433=== CONT TestService_ReadScope_PublicByDefault1434=== NAME TestOrphanedObjectsGC1435 orphaned_objects_gc_test.go:287: GC Test Summary:1436 orphaned_objects_gc_test.go:288: - Kept: 2 objects from closure A1437 orphaned_objects_gc_test.go:289: - Deleted: 2 objects from closure B1438 orphaned_objects_gc_test.go:290: - Deleted: 6 orphaned chain objects (X1->X2->X3)1439 orphaned_objects_gc_test.go:291: - Deleted: 2 orphaned single objects (Y)1440 orphaned_objects_gc_test.go:292: - Total deleted: 10 objects1441--- PASS: TestOrphanedObjectsGC (7.25s)1442=== CONT TestService_RequireScope_OIDC14432026/11/06 06:57:57 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53166/oidc14442026/11/06 06:57:57 INFO Received uploads request method=POST path=/api/pending_closures1445--- PASS: TestDeduplicatedObjectsRecordedAsPending (5.83s)1446=== CONT TestService_NativeMTLS14472026/11/06 06:57:57 INFO Received uploads request method=POST path=/api/pending_closures14482026/11/06 06:57:57 INFO Aborted multipart uploads count=0 kept=014492026/11/06 06:57:57 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=014502026/11/06 06:57:57 INFO Vacuumed table table=pending_closures14512026/11/06 06:57:57 INFO Vacuumed table table=pending_objects14522026/11/06 06:57:57 INFO Vacuumed table table=multipart_uploads14532026/11/06 06:57:57 INFO Vacuumed table table=closures14542026/11/06 06:57:57 INFO Vacuumed table table=objects14552026/11/06 06:57:57 INFO Aborted multipart uploads count=0 kept=014562026/11/06 06:57:57 WARN Force mode enabled - objects will be deleted immediately without grace period14572026/11/06 06:57:57 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=014582026/11/06 06:57:57 INFO Vacuumed table table=pending_closures14592026/11/06 06:57:57 INFO Vacuumed table table=pending_objects14602026/11/06 06:57:57 INFO Vacuumed table table=multipart_uploads14612026/11/06 06:57:57 INFO Vacuumed table table=closures14622026/11/06 06:57:57 INFO Vacuumed table table=objects1463--- PASS: TestPushDedupSurvivesConcurrentGC (6.53s)1464=== CONT TestService_AuthMiddleware_MTLSBoundSubjects14652026/11/06 06:57:57 INFO Aborted multipart uploads count=0 kept=014662026/11/06 06:57:58 WARN Force mode enabled - objects will be deleted immediately without grace period14672026/11/06 06:57:58 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=014682026/11/06 06:57:58 INFO Vacuumed table table=pending_closures14692026/11/06 06:57:58 INFO Vacuumed table table=pending_objects14702026/11/06 06:57:58 INFO Vacuumed table table=multipart_uploads14712026/11/06 06:57:58 INFO Vacuumed table table=closures14722026/11/06 06:57:58 INFO Vacuumed table table=objects1473--- PASS: TestGCMetrics (5.89s)1474=== CONT TestServerTLSConfig1475=== RUN TestServerTLSConfig/no_client_CA1476=== PAUSE TestServerTLSConfig/no_client_CA1477=== RUN TestServerTLSConfig/missing_CA_file1478=== PAUSE TestServerTLSConfig/missing_CA_file1479=== RUN TestServerTLSConfig/not_a_PEM_file1480=== PAUSE TestServerTLSConfig/not_a_PEM_file1481=== CONT TestService_ReadAuthMiddleware1482=== NAME TestPinProtectsFromGC1483 client_integration_test.go:778: Pinned store path: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestPinProtectsFromGC3538026284/001/store/vpcikbbqnqxax1b93n6yd83660dmd9sv-pinned-file.txt1484 client_integration_test.go:779: Unpinned store path: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestPinProtectsFromGC3538026284/001/store/bq9gfqj7mr3dkqplzgg5d1w9jvq66bz1-unpinned-file.txt14852026/11/06 06:57:58 INFO Received push request method=POST path=/api/pushes14862026/11/06 06:57:58 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)14872026/11/06 06:57:58 INFO Uploading vpcikbbqnqxax1b93n6yd83660dmd9sv-pinned-file.txt (128B)14882026/11/06 06:57:58 INFO lead: acquired remote=192.0.2.1:123414892026/11/06 06:57:58 WARN Failed to register uploaded object key=vpcikbbqnqxax1b93n6yd83660dmd9sv.ls error="server returned 404: 404 page not found\n"14902026/11/06 06:57:58 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign14912026/11/06 06:57:58 WARN Failed to register uploaded object key=nar/0qmhsg42pqsz7x6hh02j8gznnac3yi3qpjhrqbwvz88i194jbb5s.nar.zst error="server returned 404: 404 page not found\n"14922026/11/06 06:57:58 INFO Signed narinfos id=1 count=114932026/11/06 06:57:58 INFO Uploading 1 narinfos14942026/11/06 06:57:58 INFO Received complete push request method=POST path=/api/pushes/1/complete14952026/11/06 06:57:58 WARN Failed to register uploaded object key=vpcikbbqnqxax1b93n6yd83660dmd9sv.narinfo error="server returned 404: 404 page not found\n"14962026/11/06 06:57:58 INFO Completed push id=1 objects=3 duration=29.972792ms14972026/11/06 06:57:58 INFO Upload complete. (230ms)14982026/11/06 06:57:58 INFO Received push request method=POST path=/api/pushes14992026/11/06 06:57:58 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)15002026/11/06 06:57:58 INFO Uploading bq9gfqj7mr3dkqplzgg5d1w9jvq66bz1-unpinned-file.txt (128B)15012026/11/06 06:57:58 WARN Failed to register uploaded object key=nar/0gh0wdnr6gmk4r5sfzzh12isnl14rgmkrwy1ws41hpsrlndclg5h.nar.zst error="server returned 404: 404 page not found\n"15022026/11/06 06:57:58 INFO Received sign narinfos request method=POST path=/api/pushes/2/sign15032026/11/06 06:57:58 WARN Failed to register uploaded object key=bq9gfqj7mr3dkqplzgg5d1w9jvq66bz1.ls error="server returned 404: 404 page not found\n"15042026/11/06 06:57:58 INFO Signed narinfos id=2 count=115052026/11/06 06:57:58 INFO Uploading 1 narinfos15062026/11/06 06:57:58 INFO Received complete push request method=POST path=/api/pushes/2/complete15072026/11/06 06:57:58 WARN Failed to register uploaded object key=bq9gfqj7mr3dkqplzgg5d1w9jvq66bz1.narinfo error="server returned 404: 404 page not found\n"15082026/11/06 06:57:58 INFO Completed push id=2 objects=3 duration=808.75µs15092026/11/06 06:57:58 INFO Upload complete. (168ms)15102026/11/06 06:57:58 ERROR failed to check GC advisory lock error="query pg_locks: failed to connect to `user=_tribuchetbld7 database=niks3`: /nonexistent/.s.PGSQL.5432 (/nonexistent): dial error: dial unix /nonexistent/.s.PGSQL.5432: connect: no such file or directory"1511--- PASS: TestGCAdvisoryLockBlocksConcurrentRun (6.32s)1512=== CONT TestService_AuthMiddleware_MTLSProxyHeader15132026/11/06 06:57:58 INFO Starting cleanup of old closures method=DELETE path=/api/closures15142026/11/06 06:57:58 INFO Garbage collection started15152026/11/06 06:57:58 INFO Aborted multipart uploads count=0 kept=015162026/11/06 06:57:58 WARN Force mode enabled - objects will be deleted immediately without grace period15172026/11/06 06:57:59 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=015182026/11/06 06:57:59 INFO Vacuumed table table=pending_closures15192026/11/06 06:57:59 INFO Vacuumed table table=pending_objects15202026/11/06 06:57:59 INFO lead: acquired remote=192.0.2.1:123415212026/11/06 06:57:59 INFO Vacuumed table table=multipart_uploads15222026/11/06 06:57:59 INFO lead: released remote=192.0.2.1:12341523--- PASS: TestLeadEndsOnShutdown (6.99s)1524=== CONT TestMetricsCommit15252026/11/06 06:57:59 INFO Vacuumed table table=closures15262026/11/06 06:57:59 INFO Vacuumed table table=objects1527--- PASS: TestGCBugBareHashReferences (7.10s)1528=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info15292026/11/06 06:57:59 INFO Received uploads request method=POST path=/1530=== CONT TestPendingClosureWriteTimeout/empty1531=== CONT TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key15322026/11/06 06:57:59 INFO Received request for more parts method=POST path=/1533=== CONT TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key15342026/11/06 06:57:59 INFO Received complete multipart upload request method=POST path=/1535=== CONT TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal15362026/11/06 06:57:59 INFO Received uploads request method=POST path=/1537--- PASS: TestUploadHandlersRejectInvalidKeys (0.07s)1538 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_nix-cache-info (0.00s)1539 --- PASS: TestUploadHandlersRejectInvalidKeys/request_more_parts_rejects_non-NAR_key (0.00s)1540 --- PASS: TestUploadHandlersRejectInvalidKeys/complete_multipart_rejects_non-NAR_key (0.00s)1541 --- PASS: TestUploadHandlersRejectInvalidKeys/create_pending_closure_rejects_path_traversal (0.00s)1542=== CONT TestPendingClosureWriteTimeout/670k_objects1543=== CONT TestPendingClosureWriteTimeout/400_objects1544=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed1545--- PASS: TestConnectWaitsForAPeerMigration (6.79s)1546=== CONT TestIsValidUploadKey/narinfo1547=== CONT TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed15482026/11/06 06:58:00 INFO lead: released remote=192.0.2.1:123415492026/11/06 06:58:00 INFO lead: acquired remote=192.0.2.1:123415502026/11/06 06:58:00 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=015512026/11/06 06:58:00 INFO Received create pin request method=POST path=/api/pins/myapp15522026/11/06 06:58:00 INFO Created/updated pin name=myapp store_path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestPinProtectsFromGC3538026284/001/store/vpcikbbqnqxax1b93n6yd83660dmd9sv-pinned-file.txt narinfo_key=vpcikbbqnqxax1b93n6yd83660dmd9sv.narinfo15532026/11/06 06:58:00 INFO Starting cleanup of old closures method=DELETE path=/api/closures15542026/11/06 06:58:00 INFO Garbage collection started15552026/11/06 06:58:00 INFO Aborted multipart uploads count=0 kept=01556--- PASS: TestConcurrentCommitsSharingObjectsDoNotDeadlock (7.63s)15572026/11/06 06:58:00 INFO Received push request method=POST path=/api/pushes1558=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed15592026/11/06 06:58:00 WARN Force mode enabled - objects will be deleted immediately without grace period15602026/11/06 06:58:00 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=015612026/11/06 06:58:00 INFO Vacuumed table table=pending_closures15622026/11/06 06:58:00 INFO Vacuumed table table=pending_objects15632026/11/06 06:58:00 INFO Vacuumed table table=multipart_uploads15642026/11/06 06:58:00 INFO Vacuumed table table=closures15652026/11/06 06:58:00 INFO Vacuumed table table=objects15662026/11/06 06:58:00 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15672026/11/06 06:58:00 INFO Uploading mqz70793jv1z7d03xw0rygiifnh9xcgj-b (256B)15682026/11/06 06:58:00 INFO Uploading v2jjp2wvd1yw6yvla7j8ll625dkv8y90-shared-dep (136B)15692026/11/06 06:58:00 WARN Failed to register uploaded object key=ks05l9sr7994pv9m0b879q4d5f43nw3b.ls error="server returned 404: 404 page not found\n"15702026/11/06 06:58:00 WARN Failed to register uploaded object key=mqz70793jv1z7d03xw0rygiifnh9xcgj.ls error="server returned 404: 404 page not found\n"15712026/11/06 06:58:00 WARN Failed to register uploaded object key=v2jjp2wvd1yw6yvla7j8ll625dkv8y90.ls error="server returned 404: 404 page not found\n"15722026/11/06 06:58:00 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"15732026/11/06 06:58:00 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign15742026/11/06 06:58:00 WARN Failed to register uploaded object key=nar/0cia314nr4p221q45977r635466vig8r327rg4girwq9rbawjhh6.nar.zst error="server returned 404: 404 page not found\n"15752026/11/06 06:58:00 INFO Signed narinfos id=1 count=315762026/11/06 06:58:00 INFO Uploading 3 narinfos15772026/11/06 06:58:00 INFO Received uploads request method=POST path=/api/pending_closures15782026/11/06 06:58:00 WARN Failed to register uploaded object key=v2jjp2wvd1yw6yvla7j8ll625dkv8y90.narinfo error="server returned 404: 404 page not found\n"15792026/11/06 06:58:00 WARN Failed to register uploaded object key=ks05l9sr7994pv9m0b879q4d5f43nw3b.narinfo error="server returned 404: 404 page not found\n"15802026/11/06 06:58:00 INFO Received complete push request method=POST path=/api/pushes/1/complete15812026/11/06 06:58:00 WARN Failed to register uploaded object key=mqz70793jv1z7d03xw0rygiifnh9xcgj.narinfo error="server returned 404: 404 page not found\n"1582=== NAME TestClientMultipleUploads1583 client_integration_test.go:405: Created store path 0: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientMultipleUploads2780205117/001/store/77301fx0ky8vfphr5li5zpjhx6xh11kg-test-file-0.txt15842026/11/06 06:58:00 INFO Received uploads request method=POST path=/api/pending_closures15852026/11/06 06:58:00 INFO Uploading 2 paths to 127.0.0.1 (1 already cached)15862026/11/06 06:58:00 INFO Uploading gcwl46grr2aaqxccl172s4b6xa9yn60a-shared-dep (136B)15872026/11/06 06:58:00 INFO Uploading g86bf1ahdnnl0inc4w95pyzxcsjqh362-a (256B)15882026/11/06 06:58:00 INFO Completed push id=1 objects=8 duration=19.37525ms15892026/11/06 06:58:00 INFO Upload complete. (320ms)1590=== NAME TestClientPushesUseOnePush1591 client_pushes_test.go:97: Retrieved narinfo from S3:1592 StorePath: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientPushesUseOnePush3137129436/001/store/v2jjp2wvd1yw6yvla7j8ll625dkv8y90-shared-dep1593 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1594 Compression: zstd1595 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821596 NarSize: 1361597 References: 1598 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1599 client_pushes_test.go:97: Retrieved narinfo from S3:1600 StorePath: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientPushesUseOnePush3137129436/001/store/ks05l9sr7994pv9m0b879q4d5f43nw3b-a1601 URL: nar/0cia314nr4p221q45977r635466vig8r327rg4girwq9rbawjhh6.nar.zst1602 Compression: zstd1603 NarHash: sha256:0cia314nr4p221q45977r635466vig8r327rg4girwq9rbawjhh61604 NarSize: 2561605 References: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientPushesUseOnePush3137129436/001/store/v2jjp2wvd1yw6yvla7j8ll625dkv8y90-shared-dep1606 CA: text:sha256:1av8xjv7zbrza7k1adzmgwnsdh3a817mr7ld6szy4zbfpakvbk1k1607 client_pushes_test.go:97: Retrieved narinfo from S3:1608 StorePath: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientPushesUseOnePush3137129436/001/store/mqz70793jv1z7d03xw0rygiifnh9xcgj-b1609 URL: nar/0cia314nr4p221q45977r635466vig8r327rg4girwq9rbawjhh6.nar.zst1610 Compression: zstd1611 NarHash: sha256:0cia314nr4p221q45977r635466vig8r327rg4girwq9rbawjhh61612 NarSize: 2561613 References: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientPushesUseOnePush3137129436/001/store/v2jjp2wvd1yw6yvla7j8ll625dkv8y90-shared-dep1614 CA: text:sha256:1av8xjv7zbrza7k1adzmgwnsdh3a817mr7ld6szy4zbfpakvbk1k16152026/11/06 06:58:00 WARN Failed to register uploaded object key=nar/12b37x24h0z4ikv0ycjbakg10qbzrwh6gv1isq4w2rxr4fmj8pgk.nar.zst error="server returned 404: 404 page not found\n"16162026/11/06 06:58:00 WARN Failed to register uploaded object key=hsls8j63vfqx2371m1b6gmc8gkmlmyk0.ls error="server returned 404: 404 page not found\n"16172026/11/06 06:58:00 WARN Failed to register uploaded object key=g86bf1ahdnnl0inc4w95pyzxcsjqh362.ls error="server returned 404: 404 page not found\n"16182026/11/06 06:58:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/1/sign16192026/11/06 06:58:00 WARN Failed to register uploaded object key=gcwl46grr2aaqxccl172s4b6xa9yn60a.ls error="server returned 404: 404 page not found\n"16202026/11/06 06:58:00 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"16212026/11/06 06:58:00 INFO Signed narinfos id=1 count=216222026/11/06 06:58:00 INFO Received sign narinfos request method=POST path=/api/pending_closures/2/sign16232026/11/06 06:58:01 INFO Signed narinfos id=2 count=216242026/11/06 06:58:01 INFO Uploading 4 narinfos1625=== NAME TestClientMultipleUploads1626 client_integration_test.go:405: Created store path 1: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientMultipleUploads2780205117/001/store/qxhgl5bj0m5bpr83ry677kbs73h0qgpj-test-file-1.txt16272026/11/06 06:58:01 WARN Failed to register uploaded object key=gcwl46grr2aaqxccl172s4b6xa9yn60a.narinfo error="server returned 404: 404 page not found\n"1628--- PASS: TestClientPushesUseOnePush (7.29s)16292026/11/06 06:58:01 WARN Failed to register uploaded object key=hsls8j63vfqx2371m1b6gmc8gkmlmyk0.narinfo error="server returned 404: 404 page not found\n"1630=== CONT TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost16312026/11/06 06:58:01 WARN Failed to register uploaded object key=g86bf1ahdnnl0inc4w95pyzxcsjqh362.narinfo error="server returned 404: 404 page not found\n"1632--- PASS: TestCacheStatsHandler (6.87s)1633=== CONT TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed16342026/11/06 06:58:01 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete16352026/11/06 06:58:01 WARN Failed to register uploaded object key=gcwl46grr2aaqxccl172s4b6xa9yn60a.narinfo error="server returned 404: 404 page not found\n"1636=== NAME TestClientMultipleUploads1637 client_integration_test.go:405: Created store path 2: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientMultipleUploads2780205117/001/store/vrnrqavhd2lxjsqb84s0r4rv6x927sck-test-file-2.txt16382026/11/06 06:58:01 INFO Completed upload id=1 objects=6 duration=11.802708ms16392026/11/06 06:58:01 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete16402026/11/06 06:58:01 INFO Completed upload id=2 objects=6 duration=326.583µs16412026/11/06 06:58:01 INFO Upload complete. (445ms)1642=== NAME TestClientFallsBackToClosures1643 client_pushes_test.go:112: Retrieved narinfo from S3:1644 StorePath: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientFallsBackToClosures2792528387/001/store/gcwl46grr2aaqxccl172s4b6xa9yn60a-shared-dep1645 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1646 Compression: zstd1647 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821648 NarSize: 1361649 References: 1650 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1651 client_pushes_test.go:112: Retrieved narinfo from S3:1652 StorePath: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientFallsBackToClosures2792528387/001/store/g86bf1ahdnnl0inc4w95pyzxcsjqh362-a1653 URL: nar/12b37x24h0z4ikv0ycjbakg10qbzrwh6gv1isq4w2rxr4fmj8pgk.nar.zst1654 Compression: zstd1655 NarHash: sha256:12b37x24h0z4ikv0ycjbakg10qbzrwh6gv1isq4w2rxr4fmj8pgk1656 NarSize: 2561657 References: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientFallsBackToClosures2792528387/001/store/gcwl46grr2aaqxccl172s4b6xa9yn60a-shared-dep1658 CA: text:sha256:1z1rz2yiig0l60xghgxzp0j139bvxwmhsyhcvl05aqy0x2wldbkc1659 client_pushes_test.go:112: Retrieved narinfo from S3:1660 StorePath: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientFallsBackToClosures2792528387/001/store/hsls8j63vfqx2371m1b6gmc8gkmlmyk0-b1661 URL: nar/12b37x24h0z4ikv0ycjbakg10qbzrwh6gv1isq4w2rxr4fmj8pgk.nar.zst1662 Compression: zstd1663 NarHash: sha256:12b37x24h0z4ikv0ycjbakg10qbzrwh6gv1isq4w2rxr4fmj8pgk1664 NarSize: 2561665 References: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientFallsBackToClosures2792528387/001/store/gcwl46grr2aaqxccl172s4b6xa9yn60a-shared-dep1666 CA: text:sha256:1z1rz2yiig0l60xghgxzp0j139bvxwmhsyhcvl05aqy0x2wldbkc16672026/11/06 06:58:01 INFO Received push request method=POST path=/api/pushes1668--- PASS: TestClientFallsBackToClosures (7.51s)1669=== CONT TestIsValidUploadKey/unknown_type1670=== CONT TestIsValidUploadKey/empty_key1671=== CONT TestIsValidUploadKey/absolute1672=== CONT TestIsValidUploadKey/traversal_nar1673=== CONT TestIsValidUploadKey/traversal1674=== CONT TestIsValidUploadKey/listing_key,_narinfo_type1675=== CONT TestIsValidUploadKey/nar_key,_narinfo_type1676=== CONT TestIsValidUploadKey/narinfo_key,_nar_type1677=== CONT TestIsValidUploadKey/index.html1678=== CONT TestIsValidUploadKey/nix-cache-info1679=== CONT TestIsValidUploadKey/realisation_plus_in_output1680=== CONT TestIsValidUploadKey/realisation1681=== CONT TestIsValidUploadKey/build_log_equals1682=== CONT TestIsValidUploadKey/build_log_question_mark1683=== CONT TestIsValidUploadKey/build_log_plus_in_name1684=== CONT TestIsValidUploadKey/build_log_home-manager_file1685=== CONT TestIsValidUploadKey/build_log1686=== CONT TestIsValidUploadKey/listing1687=== CONT TestIsValidUploadKey/nar_plain1688=== CONT TestIsValidUploadKey/nar_xz1689=== CONT TestIsValidUploadKey/nar_zst1690=== CONT TestProxyWriteTimeout/narinfo1691--- PASS: TestIsValidUploadKey (0.07s)1692 --- PASS: TestIsValidUploadKey/narinfo (0.00s)1693 --- PASS: TestIsValidUploadKey/unknown_type (0.00s)1694 --- PASS: TestIsValidUploadKey/empty_key (0.00s)1695 --- PASS: TestIsValidUploadKey/absolute (0.00s)1696 --- PASS: TestIsValidUploadKey/traversal_nar (0.00s)1697 --- PASS: TestIsValidUploadKey/traversal (0.00s)1698 --- PASS: TestIsValidUploadKey/listing_key,_narinfo_type (0.00s)1699 --- PASS: TestIsValidUploadKey/nar_key,_narinfo_type (0.00s)1700 --- PASS: TestIsValidUploadKey/narinfo_key,_nar_type (0.00s)1701 --- PASS: TestIsValidUploadKey/index.html (0.00s)1702 --- PASS: TestIsValidUploadKey/nix-cache-info (0.00s)1703 --- PASS: TestIsValidUploadKey/realisation_plus_in_output (0.00s)1704 --- PASS: TestIsValidUploadKey/realisation (0.00s)1705 --- PASS: TestIsValidUploadKey/build_log_equals (0.00s)1706 --- PASS: TestIsValidUploadKey/build_log_question_mark (0.00s)1707 --- PASS: TestIsValidUploadKey/build_log_plus_in_name (0.00s)1708 --- PASS: TestIsValidUploadKey/build_log_home-manager_file (0.00s)1709 --- PASS: TestIsValidUploadKey/build_log (0.00s)1710 --- PASS: TestIsValidUploadKey/listing (0.00s)1711 --- PASS: TestIsValidUploadKey/nar_plain (0.00s)1712 --- PASS: TestIsValidUploadKey/nar_xz (0.00s)1713 --- PASS: TestIsValidUploadKey/nar_zst (0.00s)1714=== CONT TestProxyWriteTimeout/unknown_size1715=== CONT TestProxyWriteTimeout/10_GiB_nar1716=== CONT TestProxyWriteTimeout/1_GiB_nar1717--- PASS: TestProxyWriteTimeout (0.00s)1718 --- PASS: TestProxyWriteTimeout/narinfo (0.00s)1719 --- PASS: TestProxyWriteTimeout/unknown_size (0.00s)1720 --- PASS: TestProxyWriteTimeout/10_GiB_nar (0.00s)1721 --- PASS: TestProxyWriteTimeout/1_GiB_nar (0.00s)1722=== CONT TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline17232026/11/06 06:58:01 INFO Uploading 3 paths to 127.0.0.1 (0 already cached)17242026/11/06 06:58:01 INFO Uploading 77301fx0ky8vfphr5li5zpjhx6xh11kg-test-file-0.txt (160B)17252026/11/06 06:58:01 INFO Uploading qxhgl5bj0m5bpr83ry677kbs73h0qgpj-test-file-1.txt (160B)17262026/11/06 06:58:01 INFO Uploading vrnrqavhd2lxjsqb84s0r4rv6x927sck-test-file-2.txt (160B)17272026/11/06 06:58:01 WARN Failed to register uploaded object key=qxhgl5bj0m5bpr83ry677kbs73h0qgpj.ls error="server returned 404: 404 page not found\n"17282026/11/06 06:58:01 WARN Failed to register uploaded object key=nar/0ahq3izw3h0b0c08p3xdfclh758fwxnp85ccvflasb4vnfsv50ri.nar.zst error="server returned 404: 404 page not found\n"17292026/11/06 06:58:01 WARN Failed to register uploaded object key=nar/13p9pqi0ga6fx2apcwls9hjnv7nmf740ggpn5zvfzdsp5vz2bbg4.nar.zst error="server returned 404: 404 page not found\n"17302026/11/06 06:58:01 WARN Failed to register uploaded object key=77301fx0ky8vfphr5li5zpjhx6xh11kg.ls error="server returned 404: 404 page not found\n"17312026/11/06 06:58:01 WARN Failed to register uploaded object key=nar/1823g6vx4q5zqvr73m7lkq1wpk40fin7bsc792di430yk7sg4lka.nar.zst error="server returned 404: 404 page not found\n"17322026/11/06 06:58:01 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign17332026/11/06 06:58:01 WARN Failed to register uploaded object key=vrnrqavhd2lxjsqb84s0r4rv6x927sck.ls error="server returned 404: 404 page not found\n"17342026/11/06 06:58:01 INFO Signed narinfos id=1 count=317352026/11/06 06:58:01 INFO Uploading 3 narinfos17362026/11/06 06:58:01 WARN Failed to register uploaded object key=77301fx0ky8vfphr5li5zpjhx6xh11kg.narinfo error="server returned 404: 404 page not found\n"17372026/11/06 06:58:01 WARN Failed to register uploaded object key=vrnrqavhd2lxjsqb84s0r4rv6x927sck.narinfo error="server returned 404: 404 page not found\n"17382026/11/06 06:58:01 INFO Received complete push request method=POST path=/api/pushes/1/complete17392026/11/06 06:58:01 WARN Failed to register uploaded object key=qxhgl5bj0m5bpr83ry677kbs73h0qgpj.narinfo error="server returned 404: 404 page not found\n"17402026/11/06 06:58:01 INFO lead: released remote=192.0.2.1:12341741--- PASS: TestLeadElectsOneAndHandsOver (9.20s)1742=== CONT TestUploadHandlersRejectOversizedBody/create_pending_closure17432026/11/06 06:58:01 INFO Received uploads request method=POST path=/17442026/11/06 06:58:01 INFO Completed push id=1 objects=9 duration=52.203208ms17452026/11/06 06:58:01 INFO Upload complete. (399ms)1746=== NAME TestClientMultipleUploads1747 client_integration_test.go:416: Uploaded 3 paths in 441.658583ms1748--- PASS: TestClientMultipleUploads (7.66s)1749=== CONT TestUploadHandlersRejectOversizedBody/complete_multipart17502026/11/06 06:58:01 INFO Received complete multipart upload request method=POST path=/1751=== CONT TestUploadHandlersRejectOversizedBody/request_more_parts17522026/11/06 06:58:01 INFO Received request for more parts method=POST path=/1753=== CONT TestParseSingleRange/none1754=== CONT TestParseSingleRange/open-ended1755=== CONT TestParseSingleRange/start_far_past_EOF1756=== CONT TestParseSingleRange/start_past_EOF1757=== CONT TestParseSingleRange/single_byte1758=== CONT TestParseSingleRange/suffix_exceeds_size1759=== CONT TestParseSingleRange/suffix1760=== CONT TestParseSingleRange/end_clamped_to_size1761=== CONT TestParseSingleRange/malformed_both_empty1762=== CONT TestParseSingleRange/closed1763=== CONT TestParseSingleRange/malformed_end_before_start1764=== CONT TestParseSingleRange/multi-range_ignored1765=== CONT TestParseSingleRange/malformed_no_dash1766=== CONT TestParseSingleRange/unknown_unit1767--- PASS: TestParseSingleRange (0.00s)1768 --- PASS: TestParseSingleRange/none (0.00s)1769 --- PASS: TestParseSingleRange/open-ended (0.00s)1770 --- PASS: TestParseSingleRange/start_far_past_EOF (0.00s)1771 --- PASS: TestParseSingleRange/start_past_EOF (0.00s)1772 --- PASS: TestParseSingleRange/single_byte (0.00s)1773 --- PASS: TestParseSingleRange/suffix_exceeds_size (0.00s)1774 --- PASS: TestParseSingleRange/suffix (0.00s)1775 --- PASS: TestParseSingleRange/end_clamped_to_size (0.00s)1776 --- PASS: TestParseSingleRange/malformed_both_empty (0.00s)1777 --- PASS: TestParseSingleRange/closed (0.00s)1778 --- PASS: TestParseSingleRange/malformed_end_before_start (0.00s)1779 --- PASS: TestParseSingleRange/multi-range_ignored (0.00s)1780 --- PASS: TestParseSingleRange/malformed_no_dash (0.00s)1781 --- PASS: TestParseSingleRange/unknown_unit (0.00s)1782=== CONT TestIsValidCachePath/narinfo1783=== CONT TestIsValidCachePath/index.html1784=== CONT TestIsValidCachePath/short_hash1785=== CONT TestIsValidCachePath/wrong_extension1786=== CONT TestIsValidCachePath/leading_slash1787=== CONT TestIsValidCachePath/empty1788=== CONT TestIsValidCachePath/random_path1789=== CONT TestIsValidCachePath/invalid_char_u1790=== CONT TestIsValidCachePath/invalid_char_e1791=== CONT TestIsValidCachePath/traversal_in_middle1792=== CONT TestIsValidCachePath/traversal_parent1793=== CONT TestIsValidCachePath/nar_uncompressed1794=== CONT TestIsValidCachePath/nix-cache-info1795=== CONT TestIsValidCachePath/realisation1796=== CONT TestIsValidCachePath/log1797=== CONT TestIsValidCachePath/ls1798=== CONT TestIsValidCachePath/nar_xz1799=== CONT TestIsValidCachePath/nar_bz21800=== CONT TestIsValidCachePath/nar_zst1801=== CONT TestIsValidCachePath/narinfo_all_nix_base32_chars1802--- PASS: TestIsValidCachePath (0.00s)1803 --- PASS: TestIsValidCachePath/narinfo (0.00s)1804 --- PASS: TestIsValidCachePath/index.html (0.00s)1805 --- PASS: TestIsValidCachePath/short_hash (0.00s)1806 --- PASS: TestIsValidCachePath/wrong_extension (0.00s)1807 --- PASS: TestIsValidCachePath/leading_slash (0.00s)1808 --- PASS: TestIsValidCachePath/empty (0.00s)1809 --- PASS: TestIsValidCachePath/random_path (0.00s)1810 --- PASS: TestIsValidCachePath/invalid_char_u (0.00s)1811 --- PASS: TestIsValidCachePath/invalid_char_e (0.00s)1812 --- PASS: TestIsValidCachePath/traversal_in_middle (0.00s)1813 --- PASS: TestIsValidCachePath/traversal_parent (0.00s)1814 --- PASS: TestIsValidCachePath/nar_uncompressed (0.00s)1815 --- PASS: TestIsValidCachePath/nix-cache-info (0.00s)1816 --- PASS: TestIsValidCachePath/realisation (0.00s)1817 --- PASS: TestIsValidCachePath/log (0.00s)1818 --- PASS: TestIsValidCachePath/ls (0.00s)1819 --- PASS: TestIsValidCachePath/nar_xz (0.00s)1820 --- PASS: TestIsValidCachePath/nar_bz2 (0.00s)1821 --- PASS: TestIsValidCachePath/nar_zst (0.00s)1822 --- PASS: TestIsValidCachePath/narinfo_all_nix_base32_chars (0.00s)1823=== CONT TestPush_RejectsBadRequests/no_roots18242026/11/06 06:58:01 INFO Received push request method=POST path=/api/pushes1825=== CONT TestPush_RejectsBadRequests/bad_root18262026/11/06 06:58:01 INFO Received push request method=POST path=/api/pushes1827=== CONT TestPush_RejectsBadRequests/root_not_in_objects18282026/11/06 06:58:01 INFO Received push request method=POST path=/api/pushes1829=== CONT TestPush_RejectsBadRequests/no_objects18302026/11/06 06:58:01 INFO Received push request method=POST path=/api/pushes1831=== CONT TestGCEndsOnShutdown/before_the_run1832--- PASS: TestPush_RejectsBadRequests (4.71s)1833 --- PASS: TestPush_RejectsBadRequests/no_roots (0.00s)1834 --- PASS: TestPush_RejectsBadRequests/bad_root (0.00s)1835 --- PASS: TestPush_RejectsBadRequests/root_not_in_objects (0.00s)1836 --- PASS: TestPush_RejectsBadRequests/no_objects (0.00s)1837=== NAME TestClientIntegration1838 client_integration_test.go:291: Created store path: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientIntegration3274352448/002/store/vxln0vp3l5bmydw0ckgyck3kx1zphvjs-test-file.txt18392026/11/06 06:58:02 INFO Aborted multipart uploads count=1 kept=018402026/11/06 06:58:02 INFO Received cleanup request method=DELETE path=/api/pending_closures18412026/11/06 06:58:02 INFO Aborted multipart uploads count=1 kept=01842--- PASS: TestPendingCleanupUsesOneCutoff (11.82s)1843=== CONT TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark18442026/11/06 06:58:02 INFO Received push request method=POST path=/api/pushes1845--- PASS: TestUploadHandlersRejectOversizedBody (0.11s)1846 --- PASS: TestUploadHandlersRejectOversizedBody/complete_multipart (0.02s)1847 --- PASS: TestUploadHandlersRejectOversizedBody/request_more_parts (0.06s)1848 --- PASS: TestUploadHandlersRejectOversizedBody/create_pending_closure (1.20s)1849=== CONT TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete1850=== RUN TestService_AuthMiddleware_OIDC/valid_OIDC_token1851=== PAUSE TestService_AuthMiddleware_OIDC/valid_OIDC_token1852=== RUN TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1853=== PAUSE TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected1854=== RUN TestService_AuthMiddleware_OIDC/malformed_token_rejected1855=== PAUSE TestService_AuthMiddleware_OIDC/malformed_token_rejected1856=== RUN TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured1857=== PAUSE TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured18582026/11/06 06:58:02 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)18592026/11/06 06:58:02 INFO Uploading vxln0vp3l5bmydw0ckgyck3kx1zphvjs-test-file.txt (152B)1860=== CONT TestForceGCDuringPushOffersSweptObject/before_pending_rows1861=== NAME TestPinProtectsFromGC1862 client_integration_test.go:887: Pin successfully protected closure from garbage collection1863--- PASS: TestPinProtectsFromGC (11.21s)1864=== CONT TestForceGCDuringPushOffersSweptObject/after_presence_check18652026/11/06 06:58:02 WARN Failed to register uploaded object key=vxln0vp3l5bmydw0ckgyck3kx1zphvjs.ls error="server returned 404: 404 page not found\n"18662026/11/06 06:58:03 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign18672026/11/06 06:58:03 WARN Failed to register uploaded object key=nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst error="server returned 404: 404 page not found\n"18682026/11/06 06:58:03 INFO Signed narinfos id=1 count=118692026/11/06 06:58:03 INFO Uploading 1 narinfos1870=== NAME TestClientCADerivations1871 client_ca_test.go:136: Built CA derivation: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientCADerivations487978782/001/store/bh5rby1krpswiqvjzfnl5i3793x76687-ca-test18722026/11/06 06:58:03 INFO Received complete push request method=POST path=/api/pushes/1/complete18732026/11/06 06:58:03 WARN Failed to register uploaded object key=vxln0vp3l5bmydw0ckgyck3kx1zphvjs.narinfo error="server returned 404: 404 page not found\n"18742026/11/06 06:58:03 INFO Completed push id=1 objects=3 duration=20.177667ms18752026/11/06 06:58:03 INFO Upload complete. (1.03s)1876--- PASS: TestDeleteClosuresRacingPins (9.42s)1877=== CONT TestPresentNotReportedWhileGCDeletesClosure/stale1878=== NAME TestClientCADerivations1879 client_ca_test.go:139: Found 1 dependencies (including self)18802026/11/06 06:58:03 INFO All 1 paths already cached1881=== NAME TestClientIntegration1882 client_integration_test.go:317: Retrieved narinfo from S3:1883 StorePath: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientIntegration3274352448/002/store/vxln0vp3l5bmydw0ckgyck3kx1zphvjs-test-file.txt1884 URL: nar/11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk1.nar.zst1885 Compression: zstd1886 NarHash: sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11887 NarSize: 1521888 References: 1889 CA: fixed:r:sha256:11l1b7hsy9g9pz8i2rcn4n128l6pyr2yf58d49r12hr5caw9dzk11890 client_integration_test.go:318: Retrieved .ls file from S3 (compressed size: 77 bytes)1891 client_integration_test.go:318: Decompressed .ls content (64 bytes):1892 {"version":1,"root":{"type":"regular","size":39,"narOffset":96}}18932026/11/06 06:58:03 INFO Received push request method=POST path=/api/pushes18942026/11/06 06:58:03 INFO Uploading 2 paths to 127.0.0.1 (0 already cached)18952026/11/06 06:58:03 INFO Uploading zzgfw315lfgz8ldwq9c3qvn53ycq4jiq-top (264B)18962026/11/06 06:58:03 INFO Uploading p1d6f18lgsrf5iiskwv5y5ksaq6sf079-shared-dep (136B)18972026/11/06 06:58:03 WARN Failed to register uploaded object key=zzgfw315lfgz8ldwq9c3qvn53ycq4jiq.ls error="server returned 404: 404 page not found\n"18982026/11/06 06:58:03 WARN Failed to register uploaded object key=nar/02hw4ja77il5qd51pk8v3im8rin449xpc5s6ikplhcncyh55p6i6.nar.zst error="server returned 404: 404 page not found\n"18992026/11/06 06:58:03 WARN Failed to register uploaded object key=p1d6f18lgsrf5iiskwv5y5ksaq6sf079.ls error="server returned 404: 404 page not found\n"19002026/11/06 06:58:03 WARN Failed to register uploaded object key=nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst error="server returned 404: 404 page not found\n"19012026/11/06 06:58:03 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19022026/11/06 06:58:03 INFO Signed narinfos id=1 count=219032026/11/06 06:58:03 INFO Uploading 2 narinfos19042026/11/06 06:58:03 INFO Received push request method=POST path=/api/pushes19052026/11/06 06:58:03 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)19062026/11/06 06:58:03 INFO Uploading bh5rby1krpswiqvjzfnl5i3793x76687-ca-test (144B)19072026/11/06 06:58:03 WARN Failed to register uploaded object key=zzgfw315lfgz8ldwq9c3qvn53ycq4jiq.narinfo error="server returned 404: 404 page not found\n"19082026/11/06 06:58:03 INFO Received complete push request method=POST path=/api/pushes/1/complete19092026/11/06 06:58:03 WARN Failed to register uploaded object key=p1d6f18lgsrf5iiskwv5y5ksaq6sf079.narinfo error="server returned 404: 404 page not found\n"19102026/11/06 06:58:03 WARN Failed to register uploaded object key=nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst error="server returned 404: 404 page not found\n"19112026/11/06 06:58:03 WARN Failed to register uploaded object key=bh5rby1krpswiqvjzfnl5i3793x76687.ls error="server returned 404: 404 page not found\n"19122026/11/06 06:58:03 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign19132026/11/06 06:58:03 WARN Failed to register uploaded object key=log/2n786h3qsz0q70vpy71w332krfjv5a2p-ca-test.drv error="server returned 404: 404 page not found\n"19142026/11/06 06:58:03 INFO Signed narinfos id=1 count=119152026/11/06 06:58:03 INFO Uploading 1 narinfos19162026/11/06 06:58:03 INFO Completed push id=1 objects=6 duration=116.163333ms19172026/11/06 06:58:03 INFO Upload complete. (448ms)1918=== NAME TestClientSharedPathCommittedMidPush1919 client_integration_test.go:727: Retrieved narinfo from S3:1920 StorePath: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientSharedPathCommittedMidPush684673980/001/store/p1d6f18lgsrf5iiskwv5y5ksaq6sf079-shared-dep1921 URL: nar/1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y82.nar.zst1922 Compression: zstd1923 NarHash: sha256:1vnl0g6w4zgpfz06rb321mfd3jqsrs120jcl8dg2dxn014875y821924 NarSize: 1361925 References: 1926 CA: text:sha256:08nxw05k7b0pzzy0f3swvnw4ldxdbclkdnklpidwmrxdhvfrmv7n1927 client_integration_test.go:727: Retrieved narinfo from S3:19282026/11/06 06:58:03 INFO Received push request method=POST path=/api/pushes1929 StorePath: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientSharedPathCommittedMidPush684673980/001/store/zzgfw315lfgz8ldwq9c3qvn53ycq4jiq-top1930 URL: nar/02hw4ja77il5qd51pk8v3im8rin449xpc5s6ikplhcncyh55p6i6.nar.zst1931 Compression: zstd1932 NarHash: sha256:02hw4ja77il5qd51pk8v3im8rin449xpc5s6ikplhcncyh55p6i61933 NarSize: 2641934 References: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientSharedPathCommittedMidPush684673980/001/store/p1d6f18lgsrf5iiskwv5y5ksaq6sf079-shared-dep1935 CA: text:sha256:0mz94f3i9fafylz0niiz14v94a6x5i6gwsrkc26z5hw09k8iyv9119362026/11/06 06:58:03 INFO Object in database but missing from S3 key=vxln0vp3l5bmydw0ckgyck3kx1zphvjs.ls19372026/11/06 06:58:03 WARN Found objects in DB but missing from S3, will re-upload count=119382026/11/06 06:58:03 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19392026/11/06 06:58:03 INFO Received complete push request method=POST path=/api/pushes/1/complete19402026/11/06 06:58:03 WARN Failed to register uploaded object key=bh5rby1krpswiqvjzfnl5i3793x76687.narinfo error="server returned 404: 404 page not found\n"19412026/11/06 06:58:03 INFO Completed push id=1 objects=4 duration=29.776208ms19422026/11/06 06:58:03 INFO Upload complete. (432ms)19432026/11/06 06:58:03 INFO Received complete push request method=POST path=/api/pushes/2/complete19442026/11/06 06:58:03 WARN Failed to register uploaded object key=vxln0vp3l5bmydw0ckgyck3kx1zphvjs.ls error="server returned 404: 404 page not found\n"19452026/11/06 06:58:03 INFO Completed push id=2 objects=3 duration=860.875µs1946=== NAME TestClientCADerivations1947 client_ca_test.go:180: Narinfo contains CA field: StorePath: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientCADerivations487978782/001/store/bh5rby1krpswiqvjzfnl5i3793x76687-ca-test1948 URL: nar/04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n.nar.zst1949 Compression: zstd1950 NarHash: sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1951 NarSize: 1441952 References: 1953 Deriver: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientCADerivations487978782/001/store/2n786h3qsz0q70vpy71w332krfjv5a2p-ca-test.drv1954 CA: fixed:r:sha256:04jj7iiy79vhzp5kk3r2751n9x3xa44j98y5bk1ds4jp31kky74n1955 client_ca_test.go:185: Checking for realisation files in S3...19562026/11/06 06:58:03 INFO Upload complete. (152ms)1957 client_ca_test.go:207: No realisation files uploaded - this is expected for locally built CA derivations1958 client_ca_test.go:208: Locally built CA derivations don't have DrvOutput IDs until they're substituted from a cache1959=== NAME TestClientIntegration1960 client_integration_test.go:335: Retrieved .ls file from S3 (compressed size: 62 bytes)1961 client_integration_test.go:335: Decompressed .ls content (49 bytes):1962 {"version":1,"root":{"type":"regular","size":39}}1963--- PASS: TestClientSharedPathCommittedMidPush (7.99s)1964=== CONT TestPresentNotReportedWhileGCDeletesClosure/fresh1965--- PASS: TestService_ReadScope_PublicByDefault (6.98s)1966=== CONT TestResolveDBConnectionString/flag_wins1967=== CONT TestResolveDBConnectionString/PGHOST_allows_empty1968=== CONT TestResolveDBConnectionString/nothing_configured1969=== CONT TestResolveDBConnectionString/missing_file_is_an_error1970=== CONT TestResolveDBConnectionString/file_when_flag_empty1971=== CONT TestClientErrorHandling/InvalidStorePath1972--- PASS: TestResolveDBConnectionString (0.01s)1973 --- PASS: TestResolveDBConnectionString/flag_wins (0.00s)1974 --- PASS: TestResolveDBConnectionString/PGHOST_allows_empty (0.00s)1975 --- PASS: TestResolveDBConnectionString/nothing_configured (0.00s)1976 --- PASS: TestResolveDBConnectionString/missing_file_is_an_error (0.00s)1977 --- PASS: TestResolveDBConnectionString/file_when_flag_empty (0.00s)1978=== NAME TestClientCADerivations1979 client_ca_test.go:258: nix copy output: error: binary cache 's3://bucket81?endpoint=http://localhost:52889®ion=eu-west-1' is for Nix stores with prefix '/nix/store', not '/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientCADerivations487978782/001/store'1980 client_ca_test.go:259: nix copy failed (might be expected with isolated stores): exit status 11981=== NAME TestClientWithDependencies1982 client_integration_test.go:660: Built derivation: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientWithDependencies1316812385/001/store/wh2v4yvzsp5cf56x9gqgsa0615lis9fb-test-script1983--- PASS: TestClientCADerivations (9.39s)1984=== CONT TestClientErrorHandling/InvalidAuthToken1985=== NAME TestClientWithDependencies1986 client_integration_test.go:662: Found 1 dependencies (including self)19872026/11/06 06:58:03 INFO Received push request method=POST path=/api/pushes19882026/11/06 06:58:03 INFO Uploading 0 paths to 127.0.0.1 (1 already cached)19892026/11/06 06:58:04 INFO Received complete push request method=POST path=/api/pushes/3/complete19902026/11/06 06:58:04 WARN Failed to register uploaded object key=vxln0vp3l5bmydw0ckgyck3kx1zphvjs.ls error="server returned 404: 404 page not found\n"19912026/11/06 06:58:04 INFO Completed push id=3 objects=3 duration=1.136708ms19922026/11/06 06:58:04 INFO Upload complete. (129ms)1993=== NAME TestClientIntegration1994 client_integration_test.go:352: Retrieved .ls file from S3 (compressed size: 62 bytes)1995 client_integration_test.go:352: Decompressed .ls content (49 bytes):1996 {"version":1,"root":{"type":"regular","size":39}}1997 client_integration_test.go:363: Testing garbage collection...1998=== RUN TestService_RequireScope_OIDC/builder_may_write1999=== PAUSE TestService_RequireScope_OIDC/builder_may_write2000=== RUN TestService_RequireScope_OIDC/builder_may_not_admin2001=== PAUSE TestService_RequireScope_OIDC/builder_may_not_admin2002=== RUN TestService_RequireScope_OIDC/ops_may_admin2003=== PAUSE TestService_RequireScope_OIDC/ops_may_admin2004=== RUN TestService_RequireScope_OIDC/ops_may_not_write2005=== PAUSE TestService_RequireScope_OIDC/ops_may_not_write2006=== RUN TestService_RequireScope_OIDC/reader_may_not_write2007=== PAUSE TestService_RequireScope_OIDC/reader_may_not_write2008=== RUN TestService_RequireScope_OIDC/static_token_may_admin2009=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin2010=== RUN TestService_RequireScope_OIDC/static_token_may_write2011=== PAUSE TestService_RequireScope_OIDC/static_token_may_write2012=== RUN TestService_RequireScope_OIDC/reader_may_read2013=== PAUSE TestService_RequireScope_OIDC/reader_may_read2014=== RUN TestService_RequireScope_OIDC/writer_implies_read2015=== PAUSE TestService_RequireScope_OIDC/writer_implies_read2016=== RUN TestService_RequireScope_OIDC/anonymous_may_not_read2017=== PAUSE TestService_RequireScope_OIDC/anonymous_may_not_read2018=== RUN TestService_RequireScope_OIDC/reader_may_read_with_netrc2019=== PAUSE TestService_RequireScope_OIDC/reader_may_read_with_netrc2020=== RUN TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2021=== PAUSE TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2022=== RUN TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2023=== PAUSE TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2024=== RUN TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2025=== PAUSE TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2026=== CONT TestClientErrorHandling/ServerNotAvailable20272026/11/06 06:58:04 INFO Received push request method=POST path=/api/pushes20282026/11/06 06:58:04 INFO Starting cleanup of old closures method=DELETE path=/api/closures20292026/11/06 06:58:04 INFO Garbage collection started20302026/11/06 06:58:04 INFO Uploading 1 paths to 127.0.0.1 (0 already cached)20312026/11/06 06:58:04 INFO Uploading wh2v4yvzsp5cf56x9gqgsa0615lis9fb-test-script (136B)20322026/11/06 06:58:04 INFO Aborted multipart uploads count=0 kept=020332026/11/06 06:58:04 WARN Force mode enabled - objects will be deleted immediately without grace period20342026/11/06 06:58:04 WARN Failed to register uploaded object key=wh2v4yvzsp5cf56x9gqgsa0615lis9fb.ls error="server returned 404: 404 page not found\n"20352026/11/06 06:58:04 WARN Failed to register uploaded object key=nar/1s7yghixzpinyqm7g59kyn3sav81pmnsdi5v63m6x4r2vacy907j.nar.zst error="server returned 404: 404 page not found\n"20362026/11/06 06:58:04 WARN Failed to register uploaded object key=log/xkikpdfl6za8ym0xrf2jyilhwhqcx6a0-test-script.drv error="server returned 404: 404 page not found\n"20372026/11/06 06:58:04 INFO Received sign narinfos request method=POST path=/api/pushes/1/sign20382026/11/06 06:58:04 INFO Signed narinfos id=1 count=120392026/11/06 06:58:04 INFO Uploading 1 narinfos20402026/11/06 06:58:04 INFO Received complete push request method=POST path=/api/pushes/1/complete20412026/11/06 06:58:04 WARN Failed to register uploaded object key=wh2v4yvzsp5cf56x9gqgsa0615lis9fb.narinfo error="server returned 404: 404 page not found\n"20422026/11/06 06:58:04 INFO Completed push id=1 objects=4 duration=39.827041ms20432026/11/06 06:58:04 INFO Upload complete. (310ms)2044=== NAME TestClientWithDependencies2045 client_integration_test.go:664: Skipping nix copy test - isolated store (/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestClientWithDependencies1316812385/001/store) requires matching store prefix20462026/11/06 06:58:04 WARN mTLS auth: subject not in bound subjects subject="CN=reader"20472026/11/06 06:58:04 WARN mTLS auth: subject not in bound subjects subject="CN=reader"2048--- PASS: TestService_NativeMTLS (7.34s)2049=== CONT TestCacheConfigHandler/full_config,_no_issuer2050=== CONT TestCacheConfigHandler/no_signing_keys2051=== CONT TestCacheConfigHandler/no_cache_url_configured2052--- PASS: TestClientWithDependencies (8.09s)2053=== CONT TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator2054=== CONT TestServerTLSConfig/no_client_CA2055=== CONT TestServerTLSConfig/not_a_PEM_file2056--- PASS: TestCacheConfigHandler (0.06s)2057 --- PASS: TestCacheConfigHandler/full_config,_no_issuer (0.00s)2058 --- PASS: TestCacheConfigHandler/no_signing_keys (0.00s)2059 --- PASS: TestCacheConfigHandler/no_cache_url_configured (0.00s)2060 --- PASS: TestCacheConfigHandler/issuer_requested_but_no_OIDC_validator (0.00s)2061=== CONT TestServerTLSConfig/missing_CA_file2062=== CONT TestService_AuthMiddleware_OIDC/valid_OIDC_token2063=== CONT TestService_AuthMiddleware_OIDC/malformed_token_rejected20642026/11/06 06:58:04 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]2065=== CONT TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured2066=== CONT TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected2067--- PASS: TestServerTLSConfig (0.00s)2068 --- PASS: TestServerTLSConfig/no_client_CA (0.00s)2069 --- PASS: TestServerTLSConfig/missing_CA_file (0.00s)2070 --- PASS: TestServerTLSConfig/not_a_PEM_file (0.03s)20712026/11/06 06:58:04 WARN Authentication failed token_preview=eyJhbGciOi...iePxdqIGag token_length=701 oidc_error="no rule matched: claim \"repository_owner\" value [otherorg] not in allowed patterns [myorg]" oidc_provider=test tried_providers=[test]2072=== CONT TestService_RequireScope_OIDC/builder_may_write2073=== CONT TestService_RequireScope_OIDC/reader_may_read2074=== CONT TestService_RequireScope_OIDC/static_token_may_admin2075=== CONT TestService_RequireScope_OIDC/reader_may_not_write2076=== CONT TestService_RequireScope_OIDC/writer_implies_read2077--- PASS: TestService_AuthMiddleware_OIDC (7.38s)2078 --- PASS: TestService_AuthMiddleware_OIDC/valid_OIDC_token (0.00s)2079 --- PASS: TestService_AuthMiddleware_OIDC/malformed_token_rejected (0.02s)2080 --- PASS: TestService_AuthMiddleware_OIDC/static_token_still_works_with_OIDC_configured (0.00s)2081 --- PASS: TestService_AuthMiddleware_OIDC/OIDC_token_with_wrong_org_rejected (0.01s)2082=== CONT TestService_RequireScope_OIDC/static_token_may_write2083=== CONT TestService_RequireScope_OIDC/ops_may_not_write2084=== CONT TestService_RequireScope_OIDC/ops_may_admin2085=== CONT TestService_RequireScope_OIDC/builder_may_not_admin2086=== CONT TestService_RequireScope_OIDC/static_token_may_admin_with_netrc2087=== CONT TestService_RequireScope_OIDC/empty_netrc_password_may_not_read2088=== CONT TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read2089=== CONT TestService_RequireScope_OIDC/reader_may_read_with_netrc20902026/11/06 06:58:04 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]2091=== CONT TestService_RequireScope_OIDC/anonymous_may_not_read2092--- PASS: TestService_RequireScope_OIDC (7.06s)2093 --- PASS: TestService_RequireScope_OIDC/reader_may_read (0.00s)2094 --- PASS: TestService_RequireScope_OIDC/builder_may_write (0.00s)2095 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin (0.00s)2096 --- PASS: TestService_RequireScope_OIDC/reader_may_not_write (0.00s)2097 --- PASS: TestService_RequireScope_OIDC/writer_implies_read (0.00s)2098 --- PASS: TestService_RequireScope_OIDC/static_token_may_write (0.00s)2099 --- PASS: TestService_RequireScope_OIDC/ops_may_not_write (0.00s)2100 --- PASS: TestService_RequireScope_OIDC/ops_may_admin (0.00s)2101 --- PASS: TestService_RequireScope_OIDC/builder_may_not_admin (0.00s)2102 --- PASS: TestService_RequireScope_OIDC/empty_netrc_password_may_not_read (0.00s)2103 --- PASS: TestService_RequireScope_OIDC/static_token_may_admin_with_netrc (0.00s)2104 --- PASS: TestService_RequireScope_OIDC/wrong_netrc_password_may_not_read (0.01s)2105 --- PASS: TestService_RequireScope_OIDC/anonymous_may_not_read (0.00s)2106 --- PASS: TestService_RequireScope_OIDC/reader_may_read_with_netrc (0.00s)21072026/11/06 06:58:04 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=021082026/11/06 06:58:04 INFO Vacuumed table table=pending_closures21092026/11/06 06:58:04 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/present21102026/11/06 06:58:04 INFO Vacuumed table table=pending_objects21112026/11/06 06:58:04 INFO Vacuumed table table=multipart_uploads21122026/11/06 06:58:04 WARN Request failed, retrying attempt=2 backoff=219.064226ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21132026/11/06 06:58:04 INFO Vacuumed table table=closures21142026/11/06 06:58:04 INFO Vacuumed table table=objects21152026/11/06 06:58:04 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted,O=Other"21162026/11/06 06:58:04 WARN mTLS auth: bound subjects configured but subject DN unavailable21172026/11/06 06:58:04 WARN mTLS auth: subject not in bound subjects subject="CN=untrusted"2118--- PASS: TestService_AuthMiddleware_MTLSBoundSubjects (6.92s)21192026/11/06 06:58:04 WARN Request failed, retrying attempt=3 backoff=427.981383ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2120--- PASS: TestService_ReadAuthMiddleware (7.06s)21212026/11/06 06:58:05 WARN Request failed, retrying attempt=4 backoff=824.726783ms error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present2122--- PASS: TestService_AuthMiddleware_MTLSProxyHeader (6.88s)21232026/11/06 06:58:05 INFO Received uploads request method=POST path=/api/pending_closures21242026/11/06 06:58:06 INFO Garbage collection progress phase="" failed_uploads_deleted=0 old_closures_deleted=1 objects_marked=3 objects_deleted=3 objects_failed=02125=== NAME TestClientIntegration2126 client_integration_test.go:370: Objects in database after GC:2127 client_integration_test.go:370: Successfully deleted all objects with GC --force2128--- PASS: TestClientIntegration (11.87s)21292026/11/06 06:58:06 WARN Request failed, retrying attempt=5 backoff=1.477665794s error="Post \"http://localhost:19999/api/objects/present\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/objects/present21302026/11/06 06:58:06 INFO Received push request method=POST path=/api/pushes21312026/11/06 06:58:06 INFO Received complete push request method=POST path=/api/pushes/1/complete21322026/11/06 06:58:06 INFO Completed push id=1 objects=4 duration=35.002833ms21332026/11/06 06:58:06 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete21342026/11/06 06:58:06 INFO Completed upload id=2 objects=2 duration=5.266417ms2135--- PASS: TestMetricsCommit (7.29s)21362026/11/06 06:58:06 INFO Received uploads request method=POST path=/api/pending_closures21372026/11/06 06:58:07 INFO Received uploads request method=POST path=/api/pending_closures21382026/11/06 06:58:07 INFO Received uploads request method=POST path=/api/pending_closures2139=== NAME TestOrphanedObjectsGCStressTest2140 orphaned_objects_gc_test.go:422: Created 10 active closures, 5 to-delete closures, 20 orphaned chains2141 orphaned_objects_gc_test.go:440: Marked 210 objects for deletion21422026/11/06 06:58:07 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21432026/11/06 06:58:07 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-config21442026/11/06 06:58:07 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LmQ0YmE3MmQ1LTBlOGYtNDVhYy1iZDliLWM5Yjg3Mzg1YjBlZHgxNzkzOTQ4Mjg1OTExNjM3MDAw parts=1021452026/11/06 06:58:07 WARN Request failed, retrying attempt=2 backoff=198.552838ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21462026/11/06 06:58:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21472026/11/06 06:58:08 INFO Completed upload id=1 objects=3 duration=4.902292ms21482026/11/06 06:58:08 WARN Request failed, retrying attempt=3 backoff=424.596527ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21492026/11/06 06:58:08 INFO Received uploads request method=POST path=/api/pending_closures21502026/11/06 06:58:08 INFO Received uploads request method=POST path=/api/pending_closures21512026/11/06 06:58:08 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000100000000000000000000.nar.zst21522026/11/06 06:58:08 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0001.narinfo21532026/11/06 06:58:08 WARN Request failed, retrying attempt=4 backoff=833.13646ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config21542026/11/06 06:58:08 INFO Received uploads request method=POST path=/api/pending_closures21552026/11/06 06:58:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21562026/11/06 06:58:08 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LjdmNjJjNWI5LTUyM2MtNDlkZC1hODFjLTM2NTM5OTM0ZmJlY3gxNzkzOTQ4Mjg2ODA2NjQwMDAw parts=1021572026/11/06 06:58:08 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete21582026/11/06 06:58:08 INFO Completed upload id=1 objects=3 duration=14.587791ms21592026/11/06 06:58:08 INFO Received complete multipart upload request method=POST path=/api/multipart/complete21602026/11/06 06:58:09 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LmYwZTdiNDQwLWU1ZDAtNGZlNi1iNDU1LTVhNGE4MDViMDk0YXgxNzkzOTQ4Mjg3MTU5MDM3MDAw parts=1021612026/11/06 06:58:09 INFO Aborted multipart uploads count=0 kept=021622026/11/06 06:58:09 WARN Force mode enabled - objects will be deleted immediately without grace period21632026-11-06 06:58:09.132 UTC [78263] ERROR: canceling statement due to user request21642026-11-06 06:58:09.132 UTC [78263] STATEMENT: -- name: MarkStaleObjects :execrows2165 WITH RECURSIVE ct AS (2166 SELECT timezone('UTC', now()) AS now2167 ),2168 closure_reach AS (2169 -- Start with all closure keys2170 SELECT o.key, o.refs2171 FROM objects o2172 INNER JOIN closures c ON o.key = c.key2173 UNION2174 -- Recursively add all referenced objects2175 SELECT o.key, o.refs2176 FROM objects o2177 INNER JOIN closure_reach cr ON o.key = ANY(cr.refs)2178 ),2179 reachable_objects AS (2180 SELECT DISTINCT key FROM closure_reach2181 ),2182 stale_objects AS (2183 SELECT o.key2184 FROM objects AS o, ct2185 WHERE2186 NOT EXISTS (2187 SELECT 12188 FROM reachable_objects ro2189 WHERE ro.key = o.key2190 )2191 AND NOT EXISTS (2192 SELECT 12193 FROM pending_objects AS po2194 WHERE po.key = o.key2195 )2196 AND o.deleted_at IS NULL -- Only mark fresh objects2197 ORDER BY o.key COLLATE "C" -- lock in key order, like commit_pending_closure2198 FOR UPDATE2199 )2200 UPDATE objects2201 SET2202 deleted_at = ct.now,2203 first_deleted_at = COALESCE(first_deleted_at, ct.now)2204 FROM stale_objects, ct2205 WHERE objects.key = stale_objects.key2206 22072026/11/06 06:58:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22082026/11/06 06:58:09 INFO Completed upload id=1 objects=3 duration=21.704875ms22092026/11/06 06:58:09 INFO Received uploads request method=POST path=/api/pending_closures22102026/11/06 06:58:09 INFO Received uploads request method=POST path=/api/pending_closures22112026/11/06 06:58:09 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000500000000000000000000.nar.zst22122026/11/06 06:58:09 WARN Found objects in DB but missing from S3, will re-upload count=122132026/11/06 06:58:09 WARN Request failed, retrying attempt=5 backoff=1.732282101s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config2214--- PASS: TestPendingClosureWriteTimeout (0.07s)2215 --- PASS: TestPendingClosureWriteTimeout/empty (0.00s)2216 --- PASS: TestPendingClosureWriteTimeout/670k_objects (0.00s)2217 --- PASS: TestPendingClosureWriteTimeout/400_objects (0.00s)2218 --- PASS: TestPendingClosureWriteTimeout/handler_extends_the_server's_deadline (8.16s)22192026/11/06 06:58:09 INFO Received uploads request method=POST path=/api/pending_closures22202026/11/06 06:58:09 INFO Aborted multipart uploads count=0 kept=022212026/11/06 06:58:09 WARN Force mode enabled - objects will be deleted immediately without grace period22222026/11/06 06:58:09 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22232026/11/06 06:58:09 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000200000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2Ljc2OTAyMjNkLTE4ZmEtNDcyNC1iN2Q4LWY2MDY2Yjg4YzAyNXgxNzkzOTQ4Mjg3NTQyODA3MDAw parts=1022242026/11/06 06:58:09 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22252026/11/06 06:58:09 INFO Completed upload id=1 objects=3 duration=15.933292ms22262026/11/06 06:58:09 INFO Received uploads request method=POST path=/api/pending_closures22272026/11/06 06:58:09 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=022282026/11/06 06:58:09 INFO Vacuumed table table=pending_closures22292026/11/06 06:58:09 INFO Vacuumed table table=pending_objects22302026/11/06 06:58:09 INFO Vacuumed table table=multipart_uploads22312026/11/06 06:58:09 INFO Vacuumed table table=closures22322026/11/06 06:58:09 INFO Vacuumed table table=objects22332026/11/06 06:58:09 INFO Aborted multipart uploads count=0 kept=022342026/11/06 06:58:09 WARN Force mode enabled - objects will be deleted immediately without grace period22352026/11/06 06:58:09 ERROR failed to remove object object=nar/aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa.nar.zst error="Post \"http://localhost:52889/bucket101/?delete=\": context canceled"2236--- PASS: TestGCEndsOnShutdown (0.00s)2237 --- PASS: TestGCEndsOnShutdown/before_the_run (6.15s)2238 --- PASS: TestGCEndsOnShutdown/blocked_on_a_row_lock_in_the_mark (6.83s)2239 --- PASS: TestGCEndsOnShutdown/blocked_in_the_sweep's_S3_delete (7.15s)22402026/11/06 06:58:10 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22412026/11/06 06:58:10 INFO Received uploads request method=POST path=/api/pending_closures22422026/11/06 06:58:10 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2Ljg2ZDE5YTcxLTA4NTItNDFhYy05ZjMwLWE3YmM5NjIwYzdhZHgxNzkzOTQ4Mjg4MjY0NDc5MDAw parts=1022432026/11/06 06:58:10 INFO Aborted multipart uploads count=0 kept=022442026/11/06 06:58:10 WARN Force mode enabled - objects will be deleted immediately without grace period22452026/11/06 06:58:10 INFO Garbage collection completed failed-uploads-deleted=0 old-closures-deleted=0 objects-marked-for-deletion=0 objects-deleted-after-grace-period=0 objects-failed-to-delete=022462026/11/06 06:58:10 INFO Received complete upload request method=POST path=/api/pending_closures/1/complete22472026/11/06 06:58:10 INFO Vacuumed table table=pending_closures22482026/11/06 06:58:10 INFO Completed upload id=1 objects=3 duration=10.771041ms22492026/11/06 06:58:10 INFO Received uploads request method=POST path=/api/pending_closures22502026/11/06 06:58:10 INFO Vacuumed table table=pending_objects22512026/11/06 06:58:10 INFO Vacuumed table table=multipart_uploads22522026/11/06 06:58:10 INFO Vacuumed table table=closures22532026/11/06 06:58:10 INFO Vacuumed table table=objects2254--- PASS: TestForceGCDuringPushOffersSweptObject (0.00s)2255 --- PASS: TestForceGCDuringPushOffersSweptObject/before_pending_rows (7.15s)2256 --- PASS: TestForceGCDuringPushOffersSweptObject/after_presence_check (7.50s)22572026/11/06 06:58:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22582026/11/06 06:58:11 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100400000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LjFjYmYxNGQ1LTNkOTktNDRjMi1hODA4LWJlNmZlZmM4ODc2NHgxNzkzOTQ4Mjg5MjUyMTU2MDAw parts=1022592026/11/06 06:58:11 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22602026/11/06 06:58:11 INFO Completed upload id=2 objects=3 duration=421.792µs22612026/11/06 06:58:11 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"22622026/11/06 06:58:11 WARN Request failed, retrying attempt=1 backoff=100ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22632026/11/06 06:58:11 WARN Request failed, retrying attempt=2 backoff=204.22517ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22642026/11/06 06:58:11 WARN Request failed, retrying attempt=3 backoff=406.761394ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22652026/11/06 06:58:11 INFO Received uploads request method=POST path=/api/pending_closures22662026/11/06 06:58:11 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000400000000000000000000.nar.zst22672026/11/06 06:58:11 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0004.narinfo2268--- PASS: TestPresentNotReportedWhileGCDeletesClosure (0.00s)2269 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/stale (7.95s)2270 --- PASS: TestPresentNotReportedWhileGCDeletesClosure/fresh (8.12s)22712026/11/06 06:58:11 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22722026/11/06 06:58:11 INFO Received complete multipart upload request method=POST path=/api/multipart/complete22732026/11/06 06:58:11 WARN Request failed, retrying attempt=4 backoff=761.955754ms error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22742026/11/06 06:58:11 WARN Authentication failed token_preview=invalid-token token_length=13 reason="static API token mismatch"22752026/11/06 06:58:11 INFO Completed multipart upload object_key=nar/dadb44fdadb44fdadb44fdadb44f100300000000000000000000.nar.zst upload_id=MTNjZGI0NDItMGUxZC00ZTE2LTg3MDEtNWFmNWE0OTk2YWI2LmYzZDY4MDY5LWYzNmItNDQ3Mi1hNDc0LWU0MmI2M2RlMTllZHgxNzkzOTQ4MjkwMzQ0NDk4MDAw parts=1022762026/11/06 06:58:11 INFO Received complete upload request method=POST path=/api/pending_closures/2/complete22772026/11/06 06:58:11 INFO Completed upload id=2 objects=3 duration=276.459µs22782026/11/06 06:58:12 INFO Received uploads request method=POST path=/api/pending_closures22792026/11/06 06:58:12 INFO Object in database but missing from S3 key=nar/dadb44fdadb44fdadb44fdadb44f000300000000000000000000.nar.zst22802026/11/06 06:58:12 WARN Narinfo references a NAR missing from S3, will re-upload narinfo=dadb44fdadb44fdadb44fdadb44f0003.narinfo2281--- PASS: TestService_verifyS3ReuploadsStaleNarinfo (0.07s)2282 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_other_NAR_pushed (9.21s)2283 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/lost,_same_NAR_pushed (9.57s)2284 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/intact,_other_NAR_pushed (8.67s)2285 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost,_second_pushed (10.84s)2286 --- PASS: TestService_verifyS3ReuploadsStaleNarinfo/first_of_two_lost (11.11s)22872026/11/06 06:58:12 WARN Request failed, retrying attempt=5 backoff=1.592981907s error="Get \"http://localhost:19999/api/cache-config\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/cache-config22882026/11/06 06:58:14 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_closures22892026/11/06 06:58:14 WARN Request failed, retrying attempt=2 backoff=204.029849ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22902026/11/06 06:58:14 WARN Request failed, retrying attempt=3 backoff=430.050292ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22912026/11/06 06:58:14 WARN Request failed, retrying attempt=4 backoff=813.323905ms error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures22922026/11/06 06:58:15 WARN Request failed, retrying attempt=5 backoff=1.685161628s error="Post \"http://localhost:19999/api/pending_closures\": dial tcp [::1]:19999: connect: connection refused" url=http://localhost:19999/api/pending_closures2293--- PASS: TestClientErrorHandling (0.00s)2294 --- PASS: TestClientErrorHandling/InvalidStorePath (7.23s)2295 --- PASS: TestClientErrorHandling/InvalidAuthToken (8.03s)2296 --- PASS: TestClientErrorHandling/ServerNotAvailable (13.65s)2297=== NAME TestOrphanedObjectsGCStressTest2298 orphaned_objects_gc_test.go:503: Stress test completed successfully:2299 orphaned_objects_gc_test.go:504: - Active objects preserved: 202300 orphaned_objects_gc_test.go:505: - Objects deleted: 2102301 orphaned_objects_gc_test.go:506: - Total GC'd: 2102302--- PASS: TestOrphanedObjectsGCStressTest (30.07s)2303PASS2304{"timestamp":"2026-11-06T06:58:19.5239Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53373","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(9)"}2305{"timestamp":"2026-11-06T06:58:19.524725Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53294","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(2)"}2306{"timestamp":"2026-11-06T06:58:19.526872Z","level":"ERROR","message":"HTTP transport failed","event":"http_transport_failed","component":"server","subsystem":"transport","peer_addr":"127.0.0.1:53395","error_kind":"io_error","error":"Cancelled","result":"transport_error","target":"rustfs::server::http","filename":"rustfs/src/server/http.rs","line_number":2561,"threadName":"rustfs-worker","threadId":"ThreadId(8)"}23072026-11-06 06:58:19.664 UTC [77775] LOG: received smart shutdown request23082026-11-06 06:58:19.665 UTC [77775] LOG: background worker "logical replication launcher" (PID 77785) exited with exit code 123092026-11-06 06:58:19.668 UTC [77780] LOG: shutting down23102026-11-06 06:58:19.668 UTC [77780] LOG: checkpoint starting: shutdown immediate23112026-11-06 06:58:21.321 UTC [77780] LOG: checkpoint complete: wrote 12288 buffers (75.0%), wrote 5 SLRU buffers; 0 WAL file(s) added, 0 removed, 32 recycled; write=0.927 s, sync=0.696 s, total=1.653 s; sync files=36061, longest=0.001 s, average=0.001 s; distance=529898 kB, estimate=529898 kB; lsn=0/21D078C0, redo lsn=0/21D078C023122026-11-06 06:58:21.331 UTC [77775] LOG: database system is shut down2313Running OIDC tests...2314=== RUN TestAudienceForIssuer2315=== PAUSE TestAudienceForIssuer2316=== RUN TestGlobMatch2317=== PAUSE TestGlobMatch2318=== RUN TestValidateToken_ValidToken2319=== PAUSE TestValidateToken_ValidToken2320=== RUN TestValidateToken_WrongAudience2321=== PAUSE TestValidateToken_WrongAudience2322=== RUN TestValidateToken_Expired2323=== PAUSE TestValidateToken_Expired2324=== RUN TestValidateToken_BoundClaimsMismatch2325=== PAUSE TestValidateToken_BoundClaimsMismatch2326=== RUN TestValidateToken_BoundSubjectMismatch2327=== PAUSE TestValidateToken_BoundSubjectMismatch2328=== RUN TestValidateToken_MultipleProviders2329=== PAUSE TestValidateToken_MultipleProviders2330=== RUN TestValidateToken_NoMatchingProvider2331=== PAUSE TestValidateToken_NoMatchingProvider2332=== RUN TestValidateToken_KubernetesServiceAccount2333=== PAUSE TestValidateToken_KubernetesServiceAccount2334=== RUN TestNewValidator_KubernetesRequiresCA2335=== PAUSE TestNewValidator_KubernetesRequiresCA2336=== RUN TestValidateToken_KubernetesIssuerFromOwnToken2337=== PAUSE TestValidateToken_KubernetesIssuerFromOwnToken2338=== RUN TestPins_ReservedForMatchingRule2339=== PAUSE TestPins_ReservedForMatchingRule2340=== RUN TestPins_TopLevelShorthand2341=== PAUSE TestPins_TopLevelShorthand2342=== RUN TestPins_ConfigValidation2343=== PAUSE TestPins_ConfigValidation2344=== RUN TestScopes_LegacyProviderDefaultsToWrite2345=== PAUSE TestScopes_LegacyProviderDefaultsToWrite2346=== RUN TestScopes_Rules2347=== PAUSE TestScopes_Rules2348=== RUN TestScopes_ConfigValidation2349=== PAUSE TestScopes_ConfigValidation2350=== CONT TestAudienceForIssuer2351--- PASS: TestAudienceForIssuer (0.00s)2352=== CONT TestValidateToken_BoundClaimsMismatch2353=== CONT TestValidateToken_WrongAudience2354=== CONT TestValidateToken_ValidToken2355=== CONT TestGlobMatch2356=== RUN TestGlobMatch/foo_foo2357=== PAUSE TestGlobMatch/foo_foo2358=== RUN TestGlobMatch/foo_bar2359=== PAUSE TestGlobMatch/foo_bar2360=== RUN TestGlobMatch/*_2361=== CONT TestValidateToken_Expired2362=== CONT TestPins_ConfigValidation2363--- PASS: TestPins_ConfigValidation (0.00s)2364=== CONT TestScopes_ConfigValidation2365=== CONT TestScopes_Rules2366--- PASS: TestScopes_ConfigValidation (0.00s)2367=== CONT TestScopes_LegacyProviderDefaultsToWrite2368=== CONT TestPins_ReservedForMatchingRule2369=== CONT TestPins_TopLevelShorthand2370=== CONT TestValidateToken_MultipleProviders2371=== CONT TestValidateToken_KubernetesServiceAccount2372=== CONT TestValidateToken_NoMatchingProvider2373=== CONT TestValidateToken_KubernetesIssuerFromOwnToken2374=== CONT TestNewValidator_KubernetesRequiresCA2375=== CONT TestValidateToken_BoundSubjectMismatch2376=== PAUSE TestGlobMatch/*_2377=== RUN TestGlobMatch/*_anything2378=== PAUSE TestGlobMatch/*_anything2379=== RUN TestGlobMatch/foo*_foo2380=== PAUSE TestGlobMatch/foo*_foo2381=== RUN TestGlobMatch/foo*_foobar2382=== PAUSE TestGlobMatch/foo*_foobar2383=== RUN TestGlobMatch/foo*_bar2384=== PAUSE TestGlobMatch/foo*_bar2385=== RUN TestGlobMatch/*bar_bar2386=== PAUSE TestGlobMatch/*bar_bar2387=== RUN TestGlobMatch/*bar_foobar2388=== PAUSE TestGlobMatch/*bar_foobar2389=== RUN TestGlobMatch/*bar_foo2390=== PAUSE TestGlobMatch/*bar_foo2391=== RUN TestGlobMatch/foo*bar_foobar2392=== PAUSE TestGlobMatch/foo*bar_foobar2393=== RUN TestGlobMatch/foo*bar_foo123bar2394=== PAUSE TestGlobMatch/foo*bar_foo123bar2395=== RUN TestGlobMatch/foo*bar_foobarbaz2396=== PAUSE TestGlobMatch/foo*bar_foobarbaz2397=== RUN TestGlobMatch/*/*_foo/bar2398=== PAUSE TestGlobMatch/*/*_foo/bar2399=== RUN TestGlobMatch/*/*_foo2400=== PAUSE TestGlobMatch/*/*_foo2401=== RUN TestGlobMatch/refs/heads/*_refs/heads/main2402=== PAUSE TestGlobMatch/refs/heads/*_refs/heads/main2403=== RUN TestGlobMatch/refs/heads/*_refs/tags/v1.02404=== PAUSE TestGlobMatch/refs/heads/*_refs/tags/v1.02405=== RUN TestGlobMatch/refs/*/main_refs/heads/main2406=== PAUSE TestGlobMatch/refs/*/main_refs/heads/main2407=== RUN TestGlobMatch/fo?_foo2408=== PAUSE TestGlobMatch/fo?_foo2409=== RUN TestGlobMatch/fo?_fo2410=== PAUSE TestGlobMatch/fo?_fo2411=== RUN TestGlobMatch/fo?_fooo2412=== PAUSE TestGlobMatch/fo?_fooo2413=== RUN TestGlobMatch/?oo_foo2414=== PAUSE TestGlobMatch/?oo_foo2415=== RUN TestGlobMatch/?oo_boo2416=== PAUSE TestGlobMatch/?oo_boo2417=== RUN TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2418=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2419=== RUN TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2420=== PAUSE TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2421=== CONT TestGlobMatch/foo_foo2422=== CONT TestGlobMatch/*/*_foo/bar2423=== CONT TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main2424=== CONT TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main2425=== CONT TestGlobMatch/?oo_boo2426=== CONT TestGlobMatch/?oo_foo2427=== CONT TestGlobMatch/fo?_fooo2428=== CONT TestGlobMatch/fo?_fo2429=== CONT TestGlobMatch/fo?_foo2430=== CONT TestGlobMatch/refs/*/main_refs/heads/main2431=== CONT TestGlobMatch/refs/heads/*_refs/tags/v1.02432=== CONT TestGlobMatch/refs/heads/*_refs/heads/main2433=== CONT TestGlobMatch/*/*_foo2434=== CONT TestGlobMatch/*bar_bar2435=== CONT TestGlobMatch/foo*bar_foobarbaz2436=== CONT TestGlobMatch/foo*bar_foo123bar2437=== CONT TestGlobMatch/foo*bar_foobar2438=== CONT TestGlobMatch/*bar_foo2439=== CONT TestGlobMatch/*bar_foobar2440=== CONT TestGlobMatch/foo*_foo2441=== CONT TestGlobMatch/foo*_bar2442=== CONT TestGlobMatch/foo*_foobar2443=== CONT TestGlobMatch/*_2444=== CONT TestGlobMatch/*_anything2445=== CONT TestGlobMatch/foo_bar2446--- PASS: TestGlobMatch (0.04s)2447 --- PASS: TestGlobMatch/foo_foo (0.00s)2448 --- PASS: TestGlobMatch/*/*_foo/bar (0.00s)2449 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:otherorg/myrepo:ref:refs/heads/main (0.00s)2450 --- PASS: TestGlobMatch/repo:myorg/*:*_repo:myorg/myrepo:ref:refs/heads/main (0.00s)2451 --- PASS: TestGlobMatch/?oo_boo (0.00s)2452 --- PASS: TestGlobMatch/?oo_foo (0.00s)2453 --- PASS: TestGlobMatch/fo?_fooo (0.00s)2454 --- PASS: TestGlobMatch/fo?_fo (0.00s)2455 --- PASS: TestGlobMatch/fo?_foo (0.00s)2456 --- PASS: TestGlobMatch/refs/*/main_refs/heads/main (0.00s)2457 --- PASS: TestGlobMatch/refs/heads/*_refs/tags/v1.0 (0.00s)2458 --- PASS: TestGlobMatch/refs/heads/*_refs/heads/main (0.00s)2459 --- PASS: TestGlobMatch/*/*_foo (0.00s)2460 --- PASS: TestGlobMatch/*bar_bar (0.00s)2461 --- PASS: TestGlobMatch/foo*bar_foobarbaz (0.00s)2462 --- PASS: TestGlobMatch/foo*bar_foo123bar (0.00s)2463 --- PASS: TestGlobMatch/foo*bar_foobar (0.00s)2464 --- PASS: TestGlobMatch/*bar_foo (0.00s)2465 --- PASS: TestGlobMatch/*bar_foobar (0.00s)2466 --- PASS: TestGlobMatch/foo*_foo (0.00s)2467 --- PASS: TestGlobMatch/foo*_bar (0.00s)2468 --- PASS: TestGlobMatch/foo*_foobar (0.00s)2469 --- PASS: TestGlobMatch/*_ (0.00s)2470 --- PASS: TestGlobMatch/*_anything (0.00s)2471 --- PASS: TestGlobMatch/foo_bar (0.00s)24722026/11/06 06:58:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53445/oidc2473--- PASS: TestPins_ReservedForMatchingRule (0.05s)24742026/11/06 06:58:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53449/oidc24752026/11/06 06:58:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53450/oidc2476--- PASS: TestPins_TopLevelShorthand (0.05s)24772026/11/06 06:58:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53447/oidc2478--- PASS: TestScopes_Rules (0.07s)2479--- PASS: TestValidateToken_BoundSubjectMismatch (0.04s)24802026/11/06 06:58:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53453/oidc2481--- PASS: TestValidateToken_ValidToken (0.08s)24822026/11/06 06:58:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53456/oidc2483--- PASS: TestScopes_LegacyProviderDefaultsToWrite (0.08s)24842026/11/06 06:58:23 INFO OIDC provider initialized name=kubernetes issuer=https://127.0.0.1:5345524852026/11/06 06:58:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53459/oidc2486--- PASS: TestValidateToken_WrongAudience (0.09s)2487--- PASS: TestValidateToken_KubernetesServiceAccount (0.08s)24882026/11/06 06:58:23 INFO OIDC provider initialized name=kubernetes issuer=https://oidc.eks.invalid/id/ABC1232489--- PASS: TestValidateToken_KubernetesIssuerFromOwnToken (0.08s)24902026/11/06 06:58:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53463/oidc2491--- PASS: TestValidateToken_BoundClaimsMismatch (0.12s)24922026/11/06 06:58:23 http: TLS handshake error from 127.0.0.1:53466: read tcp 127.0.0.1:53465->127.0.0.1:53466: use of closed network connection2493--- PASS: TestNewValidator_KubernetesRequiresCA (0.10s)24942026/11/06 06:58:23 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:53467/oidc2495--- PASS: TestValidateToken_NoMatchingProvider (0.12s)24962026/11/06 06:58:23 INFO OIDC provider initialized name=test issuer=http://127.0.0.1:53470/oidc2497--- PASS: TestValidateToken_Expired (0.15s)24982026/11/06 06:58:23 INFO OIDC provider initialized name=provider1 issuer=http://127.0.0.1:53471/oidc24992026/11/06 06:58:23 INFO OIDC provider initialized name=provider2 issuer=http://127.0.0.1:53473/oidc2500--- PASS: TestValidateToken_MultipleProviders (0.19s)2501PASS2502Running hook tests...2503=== RUN TestSendPathsEmpty2504=== PAUSE TestSendPathsEmpty2505=== RUN TestQueueEnqueueAndFetch2506=== PAUSE TestQueueEnqueueAndFetch2507=== RUN TestQueueDeduplication2508=== PAUSE TestQueueDeduplication2509=== RUN TestQueueRemove2510=== PAUSE TestQueueRemove2511=== RUN TestQueueFetchBatchLimit2512=== PAUSE TestQueueFetchBatchLimit2513=== RUN TestQueueRetryMovesToBack2514=== PAUSE TestQueueRetryMovesToBack2515=== RUN TestQueueFetchRemoveLifecycle2516=== PAUSE TestQueueFetchRemoveLifecycle2517=== RUN TestQueueConcurrentWriters2518=== PAUSE TestQueueConcurrentWriters2519=== RUN TestQueueRemoveLargeClosure2520=== PAUSE TestQueueRemoveLargeClosure2521=== RUN TestServerClientIntegration2522--- PASS: TestServerClientIntegration (0.00s)2523=== RUN TestServerQueueError25242026/11/06 06:58:23 ERROR Failed to queue paths error="permission denied" count=12525--- PASS: TestServerQueueError (0.00s)2526=== RUN TestGetListenerSocketActivation2527 server_test.go:145: systemd socket activation does not exist on darwin2528--- SKIP: TestGetListenerSocketActivation (0.00s)2529=== RUN TestServerStalledClientDoesNotBlockShutdown2530=== PAUSE TestServerStalledClientDoesNotBlockShutdown2531=== RUN TestServerBacksOffOnAcceptErrors2532=== PAUSE TestServerBacksOffOnAcceptErrors2533=== RUN TestDrainIsolatesPoisonPath2534=== PAUSE TestDrainIsolatesPoisonPath2535=== RUN TestRunNotBlockedByPoisonHead2536=== PAUSE TestRunNotBlockedByPoisonHead2537=== RUN TestDrainGivesUpWhenServerDown2538=== PAUSE TestDrainGivesUpWhenServerDown2539=== RUN TestFailedPathPrunedByLaterClosure2540=== PAUSE TestFailedPathPrunedByLaterClosure2541=== RUN TestWorkerUploadsAndRemoves2542=== PAUSE TestWorkerUploadsAndRemoves2543=== RUN TestWorkerSkipsGCdPaths2544=== PAUSE TestWorkerSkipsGCdPaths2545=== RUN TestWorkerPrunesClosureDeps2546=== PAUSE TestWorkerPrunesClosureDeps2547=== RUN TestDrainTimeout2548=== PAUSE TestDrainTimeout2549=== RUN TestWorkerRemoveFailureIsNotProgress2550=== PAUSE TestWorkerRemoveFailureIsNotProgress2551=== RUN TestWorkerKeepsPathItCannotStat2552=== PAUSE TestWorkerKeepsPathItCannotStat2553=== CONT TestSendPathsEmpty2554=== CONT TestDrainTimeout2555=== CONT TestWorkerKeepsPathItCannotStat2556=== CONT TestWorkerRemoveFailureIsNotProgress2557--- PASS: TestSendPathsEmpty (0.00s)2558=== CONT TestDrainIsolatesPoisonPath2559=== CONT TestServerBacksOffOnAcceptErrors25602026/11/06 06:58:23 ERROR Accept failed error="too many open files"2561=== CONT TestServerStalledClientDoesNotBlockShutdown2562=== CONT TestQueueRemoveLargeClosure2563=== CONT TestQueueConcurrentWriters2564=== CONT TestQueueFetchRemoveLifecycle2565=== CONT TestWorkerUploadsAndRemoves2566=== CONT TestWorkerPrunesClosureDeps2567=== CONT TestQueueRetryMovesToBack2568=== CONT TestWorkerSkipsGCdPaths2569=== CONT TestDrainGivesUpWhenServerDown2570=== CONT TestQueueFetchBatchLimit2571=== CONT TestFailedPathPrunedByLaterClosure2572=== CONT TestRunNotBlockedByPoisonHead2573=== CONT TestQueueRemove2574=== CONT TestQueueDeduplication2575=== CONT TestQueueEnqueueAndFetch25762026/11/06 06:58:23 ERROR Accept failed error="too many open files"25772026/11/06 06:58:23 INFO Upload queue status pending=325782026/11/06 06:58:23 INFO Uploading batch count=125792026/11/06 06:58:23 ERROR Upload failed error="upload failed" count=125802026/11/06 06:58:23 INFO Upload queue status pending=225812026/11/06 06:58:23 INFO Uploading batch count=225822026/11/06 06:58:23 INFO Uploading batch count=125832026/11/06 06:58:23 ERROR Upload failed error="upload failed" count=125842026/11/06 06:58:23 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestWorkerSkipsGCdPaths751100939/002/nonexistent25852026/11/06 06:58:23 INFO Uploading batch count=425862026/11/06 06:58:23 ERROR Upload failed error="upload failed" count=42587--- PASS: TestQueueFetchBatchLimit (0.01s)25882026/11/06 06:58:23 INFO Upload queue status pending=225892026/11/06 06:58:23 INFO Uploading batch count=125902026/11/06 06:58:23 INFO Uploading batch count=12591--- PASS: TestQueueFetchRemoveLifecycle (0.01s)25922026/11/06 06:58:23 INFO Upload queue status pending=22593--- PASS: TestQueueRetryMovesToBack (0.01s)25942026/11/06 06:58:23 INFO Uploading batch count=125952026/11/06 06:58:23 WARN Cannot stat store path, will retry later path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestWorkerKeepsPathItCannotStat1402004507/002/locked/aaa error="stat /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestWorkerKeepsPathItCannotStat1402004507/002/locked/aaa: permission denied"25962026/11/06 06:58:23 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestDrainIsolatesPoisonPath2981032925/002/bbb25972026/11/06 06:58:23 INFO Uploading batch count=125982026/11/06 06:58:23 INFO Uploading batch count=225992026/11/06 06:58:23 WARN Cannot stat store path, will retry later path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestWorkerKeepsPathItCannotStat1402004507/002/locked/aaa error="stat /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestWorkerKeepsPathItCannotStat1402004507/002/locked/aaa: permission denied"2600--- PASS: TestQueueDeduplication (0.01s)26012026/11/06 06:58:23 WARN Cannot stat store path, will retry later path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestWorkerKeepsPathItCannotStat1402004507/002/locked/aaa error="stat /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestWorkerKeepsPathItCannotStat1402004507/002/locked/aaa: permission denied"2602--- PASS: TestQueueEnqueueAndFetch (0.01s)26032026/11/06 06:58:23 ERROR Drain finished with paths left in queue remaining=126042026/11/06 06:58:23 INFO Uploading batch count=126052026/11/06 06:58:23 ERROR Upload failed error="upload failed" count=126062026/11/06 06:58:23 INFO Uploading batch count=22607--- PASS: TestQueueRemove (0.01s)26082026/11/06 06:58:23 ERROR Upload failed error="upload failed" count=226092026/11/06 06:58:23 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestDrainGivesUpWhenServerDown3670970662/002/a26102026/11/06 06:58:23 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestWorkerRemoveFailureIsNotProgress3176893340/002/nonexistent26112026/11/06 06:58:23 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126122026/11/06 06:58:23 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestWorkerRemoveFailureIsNotProgress3176893340/002/nonexistent26132026/11/06 06:58:23 INFO Uploading batch count=126142026/11/06 06:58:23 ERROR Upload failed error="upload failed" count=126152026/11/06 06:58:23 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126162026/11/06 06:58:23 WARN Store path no longer exists (garbage collected?), removing from queue path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestWorkerRemoveFailureIsNotProgress3176893340/002/nonexistent26172026/11/06 06:58:23 ERROR Failed to remove paths from queue error="deleting paths: attempt to write a readonly database (8)" count=126182026/11/06 06:58:23 INFO Uploading batch count=126192026/11/06 06:58:23 ERROR Upload failed error="upload failed" count=126202026/11/06 06:58:23 ERROR Drain finished with paths left in queue remaining=126212026/11/06 06:58:23 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestDrainGivesUpWhenServerDown3670970662/002/b2622--- PASS: TestFailedPathPrunedByLaterClosure (0.01s)26232026/11/06 06:58:23 ERROR Drain finished with paths left in queue remaining=126242026/11/06 06:58:23 INFO Uploading batch count=226252026/11/06 06:58:23 ERROR Upload failed error="upload failed" count=226262026/11/06 06:58:23 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestDrainGivesUpWhenServerDown3670970662/002/c2627--- PASS: TestWorkerRemoveFailureIsNotProgress (0.02s)26282026/11/06 06:58:23 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestDrainGivesUpWhenServerDown3670970662/002/d2629--- PASS: TestWorkerKeepsPathItCannotStat (0.02s)26302026/11/06 06:58:23 INFO Uploading batch count=226312026/11/06 06:58:23 ERROR Upload failed error="upload failed" count=226322026/11/06 06:58:23 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestDrainGivesUpWhenServerDown3670970662/002/e26332026/11/06 06:58:23 ERROR Upload failed, will retry later error="upload failed" path=/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestDrainGivesUpWhenServerDown3670970662/002/f26342026/11/06 06:58:23 ERROR Drain finished with paths left in queue remaining=102635--- PASS: TestDrainIsolatesPoisonPath (0.02s)26362026/11/06 06:58:23 ERROR Accept failed error="too many open files"2637--- PASS: TestDrainGivesUpWhenServerDown (0.02s)2638--- PASS: TestWorkerSkipsGCdPaths (0.03s)2639--- PASS: TestWorkerPrunesClosureDeps (0.03s)2640--- PASS: TestWorkerUploadsAndRemoves (0.03s)26412026/11/06 06:58:23 ERROR Accept failed error="too many open files"2642--- PASS: TestQueueRemoveLargeClosure (0.04s)2643--- PASS: TestQueueConcurrentWriters (0.04s)26442026/11/06 06:58:23 ERROR Accept failed error="too many open files"26452026/11/06 06:58:23 ERROR Accept failed error="too many open files"26462026/11/06 06:58:23 ERROR Failed to decode request error="read unix /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/hook2019002443/test.sock->: i/o timeout"26472026/11/06 06:58:23 ERROR Failed to write response error="write unix /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/hook2019002443/test.sock->: i/o timeout"2648--- PASS: TestServerStalledClientDoesNotBlockShutdown (0.20s)26492026/11/06 06:58:23 ERROR Upload failed error="context deadline exceeded" count=226502026/11/06 06:58:23 ERROR Drain finished with paths left in queue remaining=42651--- PASS: TestDrainTimeout (0.22s)26522026/11/06 06:58:23 ERROR Accept failed error="too many open files"26532026/11/06 06:58:24 ERROR Accept failed error="too many open files"2654--- PASS: TestServerBacksOffOnAcceptErrors (0.64s)26552026/11/06 06:58:24 INFO Uploading batch count=126562026/11/06 06:58:24 INFO Uploading batch count=126572026/11/06 06:58:24 INFO Uploading batch count=126582026/11/06 06:58:24 ERROR Upload failed error="upload failed" count=126592026/11/06 06:58:24 INFO Uploading batch count=126602026/11/06 06:58:24 ERROR Upload failed error="upload failed" count=126612026/11/06 06:58:24 INFO Uploading batch count=126622026/11/06 06:58:24 ERROR Upload failed error="upload failed" count=126632026/11/06 06:58:24 INFO Uploading batch count=126642026/11/06 06:58:24 ERROR Upload failed error="upload failed" count=126652026/11/06 06:58:24 ERROR Drain finished with paths left in queue remaining=12666--- PASS: TestRunNotBlockedByPoisonHead (1.02s)2667PASS2668Running signing tests...2669=== RUN TestExternalSigner2670=== PAUSE TestExternalSigner2671=== RUN TestExternalSignerWrongPublicKey2672=== PAUSE TestExternalSignerWrongPublicKey2673=== RUN TestExternalSignerErrors2674=== PAUSE TestExternalSignerErrors2675=== RUN TestExternalSignerRestartsAfterCrash2676=== PAUSE TestExternalSignerRestartsAfterCrash2677=== RUN TestExternalSignerProgramErrorKeepsProcess2678=== PAUSE TestExternalSignerProgramErrorKeepsProcess2679=== RUN TestExternalSignerClose2680=== PAUSE TestExternalSignerClose2681=== RUN TestExternalSignerRejectsInvalidPublicKey2682=== PAUSE TestExternalSignerRejectsInvalidPublicKey2683=== RUN TestExternalSignerCancellation2684=== PAUSE TestExternalSignerCancellation2685=== RUN TestGenerateFingerprint2686=== PAUSE TestGenerateFingerprint2687=== RUN TestParseSigningKey2688=== PAUSE TestParseSigningKey2689=== RUN TestSign2690=== PAUSE TestSign2691=== RUN TestSignBatch2692=== PAUSE TestSignBatch2693=== RUN TestNilKeyPublicKey2694=== PAUSE TestNilKeyPublicKey2695=== RUN TestSignErrors2696=== PAUSE TestSignErrors2697=== CONT TestExternalSigner2698=== CONT TestExternalSignerCancellation2699=== CONT TestExternalSignerProgramErrorKeepsProcess2700=== CONT TestExternalSignerErrors2701=== RUN TestExternalSignerErrors/missing_signature_name2702=== PAUSE TestExternalSignerErrors/missing_signature_name2703=== CONT TestExternalSignerRejectsInvalidPublicKey2704=== RUN TestExternalSignerRejectsInvalidPublicKey/#002705=== PAUSE TestExternalSignerRejectsInvalidPublicKey/#002706=== RUN TestExternalSignerRejectsInvalidPublicKey/no-colon2707=== PAUSE TestExternalSignerRejectsInvalidPublicKey/no-colon2708=== RUN TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2709=== PAUSE TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2710=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2711=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2712=== RUN TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2713=== PAUSE TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2714=== CONT TestExternalSignerRejectsInvalidPublicKey/#002715=== RUN TestExternalSignerErrors/wrong_signature_name2716=== PAUSE TestExternalSignerErrors/wrong_signature_name2717=== RUN TestExternalSignerErrors/wrong_signature_length2718=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:invalid!2719=== CONT TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA=2720=== PAUSE TestExternalSignerErrors/wrong_signature_length2721=== RUN TestExternalSignerErrors/exit_at_startup2722=== CONT TestExternalSignerClose2723=== CONT TestSignBatch2724=== CONT TestSignErrors2725=== CONT TestNilKeyPublicKey2726--- PASS: TestNilKeyPublicKey (0.00s)2727=== CONT TestExternalSignerWrongPublicKey2728=== CONT TestParseSigningKey2729=== RUN TestParseSigningKey/valid_32-byte_key2730=== PAUSE TestParseSigningKey/valid_32-byte_key2731=== CONT TestSign2732=== CONT TestGenerateFingerprint2733=== RUN TestGenerateFingerprint/basic_with_references2734=== PAUSE TestGenerateFingerprint/basic_with_references2735=== RUN TestGenerateFingerprint/no_references2736=== PAUSE TestGenerateFingerprint/no_references2737=== RUN TestGenerateFingerprint/unsorted_references_get_sorted2738=== PAUSE TestGenerateFingerprint/unsorted_references_get_sorted2739=== CONT TestExternalSignerRejectsInvalidPublicKey/test-key:YQ==2740=== CONT TestExternalSignerRejectsInvalidPublicKey/no-colon2741=== CONT TestExternalSignerRestartsAfterCrash2742=== RUN TestGenerateFingerprint/invalid_nar_hash_prefix2743=== PAUSE TestExternalSignerErrors/exit_at_startup2744=== PAUSE TestGenerateFingerprint/invalid_nar_hash_prefix2745=== RUN TestExternalSignerErrors/null_signatures2746=== PAUSE TestExternalSignerErrors/null_signatures2747=== RUN TestExternalSignerErrors/invalid_signature_base642748=== RUN TestParseSigningKey/valid_32-byte_key_with_different_name2749=== PAUSE TestParseSigningKey/valid_32-byte_key_with_different_name2750=== RUN TestParseSigningKey/no_colon2751=== PAUSE TestParseSigningKey/no_colon2752=== RUN TestParseSigningKey/empty_name2753=== PAUSE TestParseSigningKey/empty_name2754=== RUN TestParseSigningKey/invalid_base642755=== PAUSE TestParseSigningKey/invalid_base642756=== RUN TestParseSigningKey/wrong_length2757=== PAUSE TestParseSigningKey/wrong_length2758=== CONT TestParseSigningKey/valid_32-byte_key2759--- PASS: TestExternalSignerRejectsInvalidPublicKey (0.00s)2760 --- PASS: TestExternalSignerRejectsInvalidPublicKey/#00 (0.00s)2761 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:invalid! (0.00s)2762 --- PASS: TestExternalSignerRejectsInvalidPublicKey/:AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA= (0.00s)2763 --- PASS: TestExternalSignerRejectsInvalidPublicKey/test-key:YQ== (0.00s)2764 --- PASS: TestExternalSignerRejectsInvalidPublicKey/no-colon (0.00s)2765=== CONT TestParseSigningKey/empty_name2766=== RUN TestGenerateFingerprint/invalid_nar_hash_length2767=== PAUSE TestGenerateFingerprint/invalid_nar_hash_length2768=== RUN TestGenerateFingerprint/invalid_store_path_prefix2769=== PAUSE TestGenerateFingerprint/invalid_store_path_prefix2770=== RUN TestGenerateFingerprint/invalid_reference_prefix2771=== PAUSE TestGenerateFingerprint/invalid_reference_prefix2772=== CONT TestGenerateFingerprint/basic_with_references2773=== CONT TestParseSigningKey/wrong_length2774=== CONT TestParseSigningKey/invalid_base642775=== PAUSE TestExternalSignerErrors/invalid_signature_base642776=== RUN TestExternalSignerErrors/program_error2777=== PAUSE TestExternalSignerErrors/program_error2778=== RUN TestExternalSignerErrors/wrong_shape2779=== PAUSE TestExternalSignerErrors/wrong_shape2780=== RUN TestExternalSignerErrors/wrong_signatures_shape2781=== PAUSE TestExternalSignerErrors/wrong_signatures_shape2782=== RUN TestExternalSignerErrors/exit_on_request2783=== PAUSE TestExternalSignerErrors/exit_on_request2784=== RUN TestExternalSignerErrors/null2785=== PAUSE TestExternalSignerErrors/null2786=== RUN TestExternalSignerErrors/unrequested_key2787=== PAUSE TestExternalSignerErrors/unrequested_key2788=== RUN TestExternalSignerErrors/invalid_JSON2789=== PAUSE TestExternalSignerErrors/invalid_JSON2790=== RUN TestExternalSignerErrors/wrong_id2791=== PAUSE TestExternalSignerErrors/wrong_id2792=== RUN TestExternalSignerErrors/missing_signatures2793=== PAUSE TestExternalSignerErrors/missing_signatures2794=== RUN TestExternalSignerErrors/too_few_signatures2795=== PAUSE TestExternalSignerErrors/too_few_signatures2796=== CONT TestExternalSignerErrors/missing_signature_name2797=== CONT TestExternalSignerErrors/invalid_JSON2798=== CONT TestExternalSignerErrors/unrequested_key2799=== CONT TestGenerateFingerprint/unsorted_references_get_sorted2800=== CONT TestGenerateFingerprint/invalid_reference_prefix2801=== CONT TestGenerateFingerprint/invalid_store_path_prefix2802=== CONT TestGenerateFingerprint/invalid_nar_hash_length2803=== CONT TestExternalSignerErrors/too_few_signatures2804=== CONT TestExternalSignerErrors/null2805=== CONT TestExternalSignerErrors/missing_signatures2806=== RUN TestSignErrors/nil_key2807=== PAUSE TestSignErrors/nil_key2808=== CONT TestExternalSignerErrors/exit_on_request2809=== CONT TestGenerateFingerprint/invalid_nar_hash_prefix2810=== CONT TestExternalSignerErrors/wrong_shape2811=== CONT TestParseSigningKey/valid_32-byte_key_with_different_name2812=== CONT TestExternalSignerErrors/wrong_id2813=== CONT TestExternalSignerErrors/exit_at_startup2814=== CONT TestExternalSignerErrors/null_signatures2815=== RUN TestSignErrors/nil_narinfo2816=== CONT TestParseSigningKey/no_colon2817=== CONT TestExternalSignerErrors/invalid_signature_base642818=== CONT TestExternalSignerErrors/wrong_signatures_shape2819=== CONT TestExternalSignerErrors/wrong_signature_name2820--- PASS: TestSign (0.00s)2821=== CONT TestExternalSignerErrors/program_error2822=== PAUSE TestSignErrors/nil_narinfo2823=== CONT TestExternalSignerErrors/wrong_signature_length2824=== RUN TestSignErrors/invalid_narinfo2825=== PAUSE TestSignErrors/invalid_narinfo2826=== RUN TestSignErrors/canceled2827=== PAUSE TestSignErrors/canceled2828=== CONT TestSignErrors/nil_key2829=== CONT TestSignErrors/canceled2830=== CONT TestSignErrors/invalid_narinfo2831=== CONT TestGenerateFingerprint/no_references2832--- PASS: TestParseSigningKey (0.00s)2833 --- PASS: TestParseSigningKey/empty_name (0.00s)2834 --- PASS: TestParseSigningKey/wrong_length (0.00s)2835 --- PASS: TestParseSigningKey/invalid_base64 (0.00s)2836 --- PASS: TestParseSigningKey/valid_32-byte_key (0.00s)2837 --- PASS: TestParseSigningKey/valid_32-byte_key_with_different_name (0.00s)2838 --- PASS: TestParseSigningKey/no_colon (0.00s)2839--- PASS: TestSignBatch (0.00s)2840=== CONT TestSignErrors/nil_narinfo2841--- PASS: TestSignErrors (0.01s)2842 --- PASS: TestSignErrors/nil_key (0.00s)2843 --- PASS: TestSignErrors/canceled (0.00s)2844 --- PASS: TestSignErrors/invalid_narinfo (0.00s)2845 --- PASS: TestSignErrors/nil_narinfo (0.00s)2846--- PASS: TestGenerateFingerprint (0.00s)2847 --- PASS: TestGenerateFingerprint/basic_with_references (0.00s)2848 --- PASS: TestGenerateFingerprint/unsorted_references_get_sorted (0.00s)2849 --- PASS: TestGenerateFingerprint/invalid_reference_prefix (0.00s)2850 --- PASS: TestGenerateFingerprint/invalid_store_path_prefix (0.00s)2851 --- PASS: TestGenerateFingerprint/invalid_nar_hash_length (0.00s)2852 --- PASS: TestGenerateFingerprint/invalid_nar_hash_prefix (0.00s)2853 --- PASS: TestGenerateFingerprint/no_references (0.00s)2854--- PASS: TestExternalSigner (0.24s)2855--- PASS: TestExternalSignerRestartsAfterCrash (0.44s)2856/private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestExternalSignerRestartsAfterCrash2904110136/001/sign program: line 7: /private/var/tb/7/scratch/0cd1c7d52b94a5ca/build/TestExternalSignerRestartsAfterCrash2904110136/001/sign program.starts: No such file or directory2857--- PASS: TestExternalSignerProgramErrorKeepsProcess (1.38s)2858--- PASS: TestExternalSignerCancellation (2.17s)2859--- PASS: TestExternalSignerWrongPublicKey (2.60s)2860--- PASS: TestExternalSignerClose (3.34s)2861--- PASS: TestExternalSignerErrors (0.00s)2862 --- PASS: TestExternalSignerErrors/unrequested_key (0.60s)2863 --- PASS: TestExternalSignerErrors/missing_signature_name (0.80s)2864 --- PASS: TestExternalSignerErrors/exit_at_startup (0.99s)2865 --- PASS: TestExternalSignerErrors/program_error (1.18s)2866 --- PASS: TestExternalSignerErrors/missing_signatures (1.56s)2867 --- PASS: TestExternalSignerErrors/invalid_signature_base64 (1.75s)2868 --- PASS: TestExternalSignerErrors/wrong_signature_length (1.94s)2869 --- PASS: TestExternalSignerErrors/wrong_shape (2.35s)2870 --- PASS: TestExternalSignerErrors/exit_on_request (2.75s)2871 --- PASS: TestExternalSignerErrors/too_few_signatures (2.94s)2872 --- PASS: TestExternalSignerErrors/null (3.14s)2873 --- PASS: TestExternalSignerErrors/wrong_signatures_shape (3.53s)2874 --- PASS: TestExternalSignerErrors/null_signatures (3.74s)2875 --- PASS: TestExternalSignerErrors/wrong_id (3.92s)2876 --- PASS: TestExternalSignerErrors/invalid_JSON (4.11s)2877 --- PASS: TestExternalSignerErrors/wrong_signature_name (4.30s)2878PASS2879Running OpenBao signer tests...2880=== RUN TestSign2881=== PAUSE TestSign2882=== RUN TestSignErrors2883=== PAUSE TestSignErrors2884=== RUN TestServe2885=== PAUSE TestServe2886=== RUN TestServeRejectsGarbage2887=== PAUSE TestServeRejectsGarbage2888=== CONT TestSign2889=== CONT TestSignErrors2890=== RUN TestSignErrors/http_error2891=== PAUSE TestSignErrors/http_error2892=== CONT TestServeRejectsGarbage2893=== RUN TestSignErrors/invalid_json2894=== PAUSE TestSignErrors/invalid_json2895--- PASS: TestServeRejectsGarbage (0.00s)2896=== CONT TestServe2897=== RUN TestSignErrors/no_prefix2898=== PAUSE TestSignErrors/no_prefix2899=== RUN TestSignErrors/invalid_base642900=== PAUSE TestSignErrors/invalid_base642901=== CONT TestSignErrors/http_error2902=== CONT TestSignErrors/no_prefix2903=== CONT TestSignErrors/invalid_json2904=== CONT TestSignErrors/invalid_base642905--- PASS: TestServe (0.00s)2906--- PASS: TestSignErrors (0.00s)2907 --- PASS: TestSignErrors/http_error (0.00s)2908 --- PASS: TestSignErrors/no_prefix (0.00s)2909 --- PASS: TestSignErrors/invalid_json (0.00s)2910 --- PASS: TestSignErrors/invalid_base64 (0.00s)2911--- PASS: TestSign (0.00s)2912PASS