diff --git a/.env b/.env index 7c7e415c..eee164cf 100644 --- a/.env +++ b/.env @@ -25,8 +25,6 @@ APP_INVOICE_SUPPLIER_ACCOUNT=APP_INVOICE_SUPPLIER_ACCOUNT APP_INVOICE_EXTERNAL_RECEIVER_ACCOUNT= APP_INVOICE_DESCRIPTION_TEMPLATE="Spørgsmål vedrørende fakturaen rettes til %name%, %email%." APP_PROJECT_BILLING_DEFAULT_DESCRIPTION= -APP_HTTP_CLIENT_RETRY_DELAY_MS=1000 -APP_HTTP_CLIENT_MAX_RETRIES=3 EMAIL_FROM_ADDRESS= ###> itk-dev/openid-connect-bundle ### diff --git a/CHANGELOG.md b/CHANGELOG.md index 012f93ee..9c36829f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,40 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +* [PR-327](https://github.com/itk-dev/economics/pull/327) + * Recorded where the 429s came from, since nothing here did and the answer is not in the data-api plugin. + Leantime core rate-limits every request in `app/Core/Middleware/RequestRateLimiter.php` (v3.9.7): the API + bucket defaults to **100 requests per 60 seconds, keyed on client IP**, and the 429 carries `Retry-After` + plus three `X-RateLimit-*` headers. It reaches `/APIData/API/…` because `IncomingRequest::isApiRequest()` + lowercases the URI and prefix-matches `/api`. It is disabled outright when `app.debug` is true, which is + why development never saw it. **What resolved the 429s was raising `LEAN_RATELIMIT_API` to 10000 on the + Leantime side**, not anything in this repository — a full sync cannot approach that. + * Respaced the `async` transport's `retry_strategy`. Three attempts was never the problem; 1s/2s/4s was, being + over before anything transient has had time to end. Now 10s, 30s, 90s, so the last attempt lands 130s after + the first failure — past a Leantime restart, a database failover, or a 60s rate-limit window. No wider than + that, because a page only queues its successor once it succeeds: a page waiting to be retried is the whole + entity type's sync waiting with it, against an hourly cron. This applies to every message on the transport, + not only the Leantime ones. PR-325 and PR-326 already narrowed the handlers so only a failure describing the + message itself is unrecoverable, which is what lets a transient failure reach the queue at all. + * A 4xx other than 408/423/425/429 now fails the message immediately instead of being retried three times to + arrive at the same answer — the endpoint returns 400 for a missing `type` or the retired `deleted` + parameter, and the retry budget cannot rewrite the request. This is the delete sync's only cover: + `sync-deleted` dispatches on the `sync` transport, which has no retry strategy, and it has to stay there — + what keeps `DELETED_TYPES` in child-before-parent order is the handlers running inline. + * Bounded Leantime requests with `timeout: 5` and `max_duration: 30` on a client of their own rather than on + `framework.http_client.default_options`, so nothing else inherits them. Symfony caps neither by default and + an uncapped request holds the worker forever, since `messenger:consume` only checks `--time-limit` between + messages. A scoped client cannot express this: scopes key on `base_uri`, and the Leantime one comes from the + `DataProvider` entity at runtime. + * Dropped `--failure-limit=1` from the supervisor's `messenger:consume`. `StopWorkerOnFailureLimitListener` + counts every `WorkerMessageFailedEvent`, which the worker dispatches for retryable failures too, so with one + worker configured the first transient error stopped it — now that a retry ladder exists, that is the wrong + thing to count. + * Considered and rejected throttling the client with a `ThrottlingHttpClient` over a rate limiter. Against the + configured 10000/min it would guard nothing, and it pauses inside the message handler, so the single worker + stops draining the queue while it waits. Retrying is also the layer that cannot read the `Retry-After` + Leantime sends — a transport retry strategy never sees the response — but the ladder above outlasts a 60s + window by its third attempt, so the header would not change the outcome. * [PR-335](https://github.com/itk-dev/economics/pull/335) * Stopped `projectRemovedFromDataProvider()` hard-deleting a project that a version, a project billing or a service agreement still points at. Each of those points back with a non-nullable, non-cascading foreign key, diff --git a/config/packages/messenger.yaml b/config/packages/messenger.yaml index 23b565cc..0b6fce01 100644 --- a/config/packages/messenger.yaml +++ b/config/packages/messenger.yaml @@ -8,6 +8,20 @@ framework: # @see https://symfony.com/doc/current/messenger.html#transport-configuration async: dsn: "%env(MESSENGER_TRANSPORT_DSN)%" + # Symfony's three attempts are the right number; 1s/2s/4s is the wrong spacing, over + # before anything transient has had time to end. Widened to 10s, 30s, 90s, so the + # last attempt lands 130s after the first failure — past a Leantime restart, a + # database failover, or a 60s rate-limit window. + # + # Not widened further: a page only queues its successor once it succeeds, so a page + # waiting to be retried is the whole entity type's sync waiting with it, against an + # hourly cron. This applies to every message on the transport, not only the Leantime + # ones — the handlers mark a failure unrecoverable only when it describes the message + # itself, so anything transient reaches the transport. + retry_strategy: + max_retries: 3 + delay: 10000 + multiplier: 3 # @see https://symfony.com/doc/current/messenger.html#saving-retrying-failed-messages failed: dsn: "%env(MESSENGER_TRANSPORT_DSN_FAILED)%" diff --git a/config/services.yaml b/config/services.yaml index 46311bef..73370ea5 100644 --- a/config/services.yaml +++ b/config/services.yaml @@ -64,3 +64,26 @@ services: App\Command\SyncCommand: arguments: $monitoringUrl: "%env(string:SYNC_MONITORING_URL)%" + + # A full sync makes hundreds of paged requests to one host, so the Leantime caller gets bounds of + # its own; framework.http_client.default_options stays untouched so nothing else inherits them. + # + # A scoped client cannot express this: scopes key on base_uri, and the Leantime base URI comes + # from the DataProvider entity at runtime, not from config. + # + # Deliberately not a RetryableHttpClient. Every Leantime fetch is driven by a message the async + # transport already retries, and retrying underneath the queue only hides the failure from it. + app.leantime.http_client: + class: Symfony\Contracts\HttpClient\HttpClientInterface + factory: ["@http_client", withOptions] + arguments: + # timeout is the idle gap between chunks, not the whole request, so 5s is generous for an + # API that answers in milliseconds. max_duration bounds one page; if a page ever needs + # longer, lower LeantimeApiService::LIMIT rather than raising this. Symfony caps neither + # by default, and an uncapped request holds the worker forever: messenger:consume only + # checks --time-limit between messages, never during one. + - { timeout: 5, max_duration: 30 } + + App\Service\LeantimeApiService: + arguments: + $httpClient: "@app.leantime.http_client" diff --git a/docker-compose.server.override.yml b/docker-compose.server.override.yml index 7fb442eb..d3abfdd3 100644 --- a/docker-compose.server.override.yml +++ b/docker-compose.server.override.yml @@ -31,10 +31,15 @@ services: restart: unless-stopped stop_grace_period: 20s environment: - - APP_SUPERVISOR_COMMAND=/app/bin/console messenger:consume --env=prod --no-debug --time-limit=900 --failure-limit=1 async + # No --failure-limit: StopWorkerOnFailureLimitListener counts every WorkerMessageFailedEvent, + # which the worker dispatches for retryable failures too, so a limit of 1 stopped the only + # worker on the first transient error rather than on anything final. --time-limit still recycles + # the process, and a message that genuinely fails ends up in the failed transport either way. + - APP_SUPERVISOR_COMMAND=/app/bin/console messenger:consume --env=prod --no-debug --time-limit=900 async - APP_SUPERVISOR_WORKERS=1 - APP_SUPERVISOR_USER=deploy - # Sync job is rate limited by LeanTime API so it will take some time to complete. + # A backstop only: --time-limit above ends the process first, and the Leantime client caps a + # single request at max_duration: 30s, so nothing inside one message runs anywhere near this. - PHP_MAX_EXECUTION_TIME=1800 - PHP_MEMORY_LIMIT=512M - PHP_TIMEZONE=UTC diff --git a/src/MessageHandler/LeantimeDeleteHandler.php b/src/MessageHandler/LeantimeDeleteHandler.php index 63fd8ed3..d494d422 100644 --- a/src/MessageHandler/LeantimeDeleteHandler.php +++ b/src/MessageHandler/LeantimeDeleteHandler.php @@ -4,14 +4,18 @@ use App\Exception\NotFoundException; use App\Message\LeantimeDeleteMessage; +use App\MessageHandler\Trait\RethrowsTransientHttpFailuresTrait; use App\Service\LeantimeApiService; use Psr\Log\LoggerInterface; use Symfony\Component\Messenger\Attribute\AsMessageHandler; use Symfony\Component\Messenger\Exception\UnrecoverableMessageHandlingException; +use Symfony\Contracts\HttpClient\Exception\ClientExceptionInterface; #[AsMessageHandler] readonly class LeantimeDeleteHandler { + use RethrowsTransientHttpFailuresTrait; + public function __construct( private LoggerInterface $logger, private LeantimeApiService $leantimeApiService, @@ -36,6 +40,8 @@ public function __invoke(LeantimeDeleteMessage $message): void $message->asyncJobQueue, $message->deletedAfter, ); + } catch (ClientExceptionInterface $e) { + $this->rethrowUnlessPermanent($e, $this->logger); } catch (NotFoundException|\TypeError $e) { // Narrow on purpose: see UpsertIssueHandler. Infrastructure failures must propagate. $this->logger->error($e->getMessage()); diff --git a/src/MessageHandler/LeantimeUpdateHandler.php b/src/MessageHandler/LeantimeUpdateHandler.php index d10bb99d..93ee0852 100644 --- a/src/MessageHandler/LeantimeUpdateHandler.php +++ b/src/MessageHandler/LeantimeUpdateHandler.php @@ -4,14 +4,18 @@ use App\Exception\NotFoundException; use App\Message\LeantimeUpdateMessage; +use App\MessageHandler\Trait\RethrowsTransientHttpFailuresTrait; use App\Service\LeantimeApiService; use Psr\Log\LoggerInterface; use Symfony\Component\Messenger\Attribute\AsMessageHandler; use Symfony\Component\Messenger\Exception\UnrecoverableMessageHandlingException; +use Symfony\Contracts\HttpClient\Exception\ClientExceptionInterface; #[AsMessageHandler] readonly class LeantimeUpdateHandler { + use RethrowsTransientHttpFailuresTrait; + public function __construct( private LoggerInterface $logger, private LeantimeApiService $leantimeApiService, @@ -33,6 +37,8 @@ public function __invoke(LeantimeUpdateMessage $message): void $message->modifiedAfter, $message->disableModifiedAtCheck, ); + } catch (ClientExceptionInterface $e) { + $this->rethrowUnlessPermanent($e, $this->logger); } catch (NotFoundException|\TypeError $e) { // Narrow on purpose: see UpsertIssueHandler. A page that fails because Leantime or the // database is unavailable must be retried, not dropped along with the pages after it. diff --git a/src/MessageHandler/Trait/RethrowsTransientHttpFailuresTrait.php b/src/MessageHandler/Trait/RethrowsTransientHttpFailuresTrait.php new file mode 100644 index 00000000..c69a2abd --- /dev/null +++ b/src/MessageHandler/Trait/RethrowsTransientHttpFailuresTrait.php @@ -0,0 +1,36 @@ +getResponse()->getStatusCode(), self::RETRY_LATER_STATUS_CODES, true)) { + throw $e; + } + + $logger->error($e->getMessage()); + + throw new UnrecoverableMessageHandlingException($e->getMessage()); + } +} diff --git a/tests/Integration/Service/LeantimeApiClientTest.php b/tests/Integration/Service/LeantimeApiClientTest.php new file mode 100644 index 00000000..e62abb24 --- /dev/null +++ b/tests/Integration/Service/LeantimeApiClientTest.php @@ -0,0 +1,71 @@ +assertNotSame( + self::getContainer()->get('http_client'), + $this->leantimeHttpClient(), + 'Drop the explicit $httpClient argument and the service autowires the unbounded shared client.', + ); + } + + public function testLeantimeClientIsBounded(): void + { + $options = $this->defaultOptions($this->leantimeHttpClient()); + + $this->assertSame(5.0, (float) $options['timeout'], 'Idle gap between chunks.'); + $this->assertSame(30.0, (float) $options['max_duration'], 'Whole request, one page.'); + } + + private function leantimeHttpClient(): HttpClientInterface + { + self::bootKernel(); + + $service = self::getContainer()->get(LeantimeApiService::class); + $client = (new \ReflectionProperty($service, 'httpClient'))->getValue($service); + + $this->assertInstanceOf(HttpClientInterface::class, $client); + + return $client; + } + + /** + * The options the client was built with. Symfony's clients keep them in a `defaultOptions` + * property and its decorators hold the one they wrap in `client`, so walking the stack finds + * whichever layer carries them — the profiler wraps this one in test. + * + * @return array + */ + private function defaultOptions(HttpClientInterface $client): array + { + while (!property_exists($client, 'defaultOptions')) { + $this->assertTrue(property_exists($client, 'client'), 'No layer of the client carries default options.'); + + $inner = (new \ReflectionProperty($client, 'client'))->getValue($client); + $this->assertInstanceOf(HttpClientInterface::class, $inner); + + $client = $inner; + } + + return (new \ReflectionProperty($client, 'defaultOptions'))->getValue($client); + } +} diff --git a/tests/Unit/MessageHandler/LeantimeDeleteHandlerTest.php b/tests/Unit/MessageHandler/LeantimeDeleteHandlerTest.php index 806f1cf2..4cc98170 100644 --- a/tests/Unit/MessageHandler/LeantimeDeleteHandlerTest.php +++ b/tests/Unit/MessageHandler/LeantimeDeleteHandlerTest.php @@ -8,10 +8,58 @@ use App\Service\LeantimeApiService; use PHPUnit\Framework\TestCase; use Psr\Log\LoggerInterface; +use Symfony\Component\HttpClient\Exception\ClientException; +use Symfony\Component\HttpClient\MockHttpClient; +use Symfony\Component\HttpClient\Response\MockResponse; use Symfony\Component\Messenger\Exception\UnrecoverableMessageHandlingException; class LeantimeDeleteHandlerTest extends TestCase { + /** + * The endpoint answers 400 to a missing `type` or the retired `deleted` parameter, and no amount + * of retrying rewrites the request. + */ + public function testInvokeOnPermanentClientErrorThrowsUnrecoverable(): void + { + $message = new LeantimeDeleteMessage(LeantimeApiService::TIMESHEETS, 0, 100, 1, false, null); + + $service = $this->createMock(LeantimeApiService::class); + $service->method('deleteAsJob')->willThrowException($this->clientException(400)); + + $handler = new LeantimeDeleteHandler($this->createMock(LoggerInterface::class), $service); + + $this->expectException(UnrecoverableMessageHandlingException::class); + $handler($message); + } + + public function testInvokeOnRateLimitPropagates(): void + { + $message = new LeantimeDeleteMessage(LeantimeApiService::TIMESHEETS, 0, 100, 1, false, null); + + $service = $this->createMock(LeantimeApiService::class); + $service->method('deleteAsJob')->willThrowException($this->clientException(429)); + + $handler = new LeantimeDeleteHandler($this->createMock(LoggerInterface::class), $service); + + try { + $handler($message); + $this->fail('Expected the rate limit to propagate.'); + } catch (ClientException $e) { + $this->assertSame(429, $e->getResponse()->getStatusCode()); + } + } + + private function clientException(int $statusCode): ClientException + { + $client = new MockHttpClient(new MockResponse('', ['http_code' => $statusCode])); + $response = $client->request('POST', 'https://leantime.example.com/APIData/API/deleted'); + + // Reading the code settles the mock, so ClientException finds the info it formats from. + $response->getStatusCode(); + + return new ClientException($response); + } + public function testInvokeCallsDeleteAsJob(): void { $deletedAfter = new \DateTime('2024-01-01'); diff --git a/tests/Unit/MessageHandler/LeantimeUpdateHandlerTest.php b/tests/Unit/MessageHandler/LeantimeUpdateHandlerTest.php index c6490f32..59d173b2 100644 --- a/tests/Unit/MessageHandler/LeantimeUpdateHandlerTest.php +++ b/tests/Unit/MessageHandler/LeantimeUpdateHandlerTest.php @@ -8,10 +8,62 @@ use App\Service\LeantimeApiService; use PHPUnit\Framework\TestCase; use Psr\Log\LoggerInterface; +use Symfony\Component\HttpClient\Exception\ClientException; +use Symfony\Component\HttpClient\MockHttpClient; +use Symfony\Component\HttpClient\Response\MockResponse; use Symfony\Component\Messenger\Exception\UnrecoverableMessageHandlingException; class LeantimeUpdateHandlerTest extends TestCase { + /** + * A 4xx that Leantime will answer the same way next time. Retrying spends the whole backoff to + * arrive back here, so the message is dropped instead. + */ + public function testInvokeOnPermanentClientErrorThrowsUnrecoverable(): void + { + $message = new LeantimeUpdateMessage('App\Entity\Project', 0, 100, 1, false, null); + + $service = $this->createMock(LeantimeApiService::class); + $service->method('updateAsJob')->willThrowException($this->clientException(400)); + + $handler = new LeantimeUpdateHandler($this->createMock(LoggerInterface::class), $service); + + $this->expectException(UnrecoverableMessageHandlingException::class); + $handler($message); + } + + /** + * The regression this branch exists for: a rate-limited page must reach the transport unwrapped, + * so the async retry strategy queues it again instead of the sync ending here. + */ + public function testInvokeOnRateLimitPropagates(): void + { + $message = new LeantimeUpdateMessage('App\Entity\Project', 0, 100, 1, false, null); + + $service = $this->createMock(LeantimeApiService::class); + $service->method('updateAsJob')->willThrowException($this->clientException(429)); + + $handler = new LeantimeUpdateHandler($this->createMock(LoggerInterface::class), $service); + + try { + $handler($message); + $this->fail('Expected the rate limit to propagate.'); + } catch (ClientException $e) { + $this->assertSame(429, $e->getResponse()->getStatusCode()); + } + } + + private function clientException(int $statusCode): ClientException + { + $client = new MockHttpClient(new MockResponse('', ['http_code' => $statusCode])); + $response = $client->request('POST', 'https://leantime.example.com/APIData/API/projects'); + + // Reading the code settles the mock, so ClientException finds the info it formats from. + $response->getStatusCode(); + + return new ClientException($response); + } + public function testInvokeCallsUpdateAsJob(): void { $modifiedAfter = new \DateTime('2024-01-01');