diff --git a/COMPENDIUM.md b/COMPENDIUM.md index 31ac4d2..f5a9bfa 100644 --- a/COMPENDIUM.md +++ b/COMPENDIUM.md @@ -114,7 +114,7 @@ Arcanum has opinions about the front end. They aren't required — you can swap - **Validation** — Attribute-based validation on DTO constructor params. 11 built-in rules: `NotEmpty`, `MinLength`, `MaxLength`, `Min`, `Max`, `Email`, `Pattern`, `In`, `Url`, `Uuid`, `Callback`. `ValidationGuard` Conveyor middleware fires before handlers. Custom rules via the `Rule` interface. - **Glitch** — Error/exception/shutdown handling. `ExceptionHandler`, `ExceptionRenderer`, `HttpException` with the full `StatusCode` enum. `ArcanumException` interface gives every framework exception a `getTitle()` and `getSuggestion()` (RFC 9457 forward-compatible). -- **Quill** — Multi-channel PSR-3 logger over Monolog. `ChannelLogger` for named channels. +- **Quill** — Multi-channel PSR-3 logger over Monolog. `ChannelLogger` for named channels. `CorrelationProcessor` tags every log record with a `correlation_id` for grouping related lines within a unit of work. - **Echo** — PSR-14 event dispatcher. Uses Flow Pipeline internally. Stoppable propagation, mutable events. - **Throttle** — Rate limiting. `Throttler` interface, `TokenBucket` and `SlidingWindow` strategies, `RateLimiter`, `Quota` value object with `isAllowed()` and `headers()` (X-RateLimit-* + Retry-After). - **Testing** — Test harness for app developers. `TestKernel` builds a shared Cabinet container with a `FrozenClock` (pinned at `2026-01-01`), an `ArrayDriver` cache, and an `ActiveIdentity`, then exposes lazy `http()` / `cli()` surfaces that wrap real `HyperKernel` / `RuneKernel` instances bootstrapping against that same container — so cross-transport tests share state and `actingAs($identity)` set on the parent kernel is visible from both. `HttpTestSurface` translates fluent `get/post/put/patch/delete` calls into real PSR-7 `ServerRequest`s with persistent `withHeader()`; `CliTestSurface::run(argv)` returns a `CliResult` (`exitCode`, `stdout`, `stderr`) backed by a fresh `BufferedOutput` per call. Both surfaces support fixture-handler injection (`setCoreHandler` / `setRunner`) for round-trip dispatch tests. `Factory::make($class, $overrides)` produces valid DTOs by composing `Codex\Hydrator` and synthesizing values from validation attributes for any constructor parameter without an override or default — recurses into nested DTOs, throws `FactoryException` (an `ArcanumException`) on `#[Pattern]`/`#[Callback]` with a "provide an override" hint. The internal kernels use empty bootstrappers lists so they don't re-run the production chain and stomp the test bindings; future production-bootstrapper opt-in (`withDatabase()`, etc.) is a builder-shape question for later. @@ -123,6 +123,47 @@ Arcanum has opinions about the front end. They aren't required — you can swap --- +## Framework logging + +The framework logs decisions, not data. Every log call uses null-safe `$this->logger?->method()` — when no logger is configured, it short-circuits with zero cost. + +**Correlation.** `Bootstrap\Logger` registers a `CorrelationProcessor` on every Monolog channel. The kernels generate a random 16-character hex ID at the start of each `handle()` cycle and clear it afterward. Every log line emitted during that cycle carries the same `correlation_id` in its extra data, making interleaved concurrent requests easy to trace. Note: correlation IDs are a Monolog processor feature — apps that bind a custom non-Monolog `LoggerInterface` before `Bootstrap\Logger` runs will need to implement their own correlation mechanism. + +**One INFO line per request.** The "access log" is a single INFO entry when the request completes: method, path, status code (HTTP) or command name and exit code (CLI). Everything else is DEBUG or NOTICE. + +**What the framework logs:** + +| Component | Level | What | +|---|---|---| +| HyperKernel | DEBUG | Request received (method, path) | +| HyperKernel | INFO | Request handled (method, path, status) | +| RuneKernel | DEBUG | Command received (name) | +| RuneKernel | INFO | Command completed (name, exit code) | +| HttpRouter | DEBUG | Route resolved (type, DTO class, format) | +| HttpRouter | DEBUG | Route not found (path) | +| HttpRouter | NOTICE | Method not allowed (path, method, allowed) | +| HttpRouter | NOTICE | Format not acceptable (format, allowed) | +| CliRouter | DEBUG | Command resolved (type, DTO class) | +| CliRouter | DEBUG | Command not found (input) | +| RouteDispatcher | DEBUG | Dispatching (DTO class, handler prefix, middleware counts) | +| AuthMiddleware | INFO | Identity resolved (guard type) | +| AuthMiddleware | DEBUG | No identity resolved | +| SessionMiddleware | DEBUG | Session started / loaded / saved | +| SessionMiddleware | NOTICE | Session regenerated / invalidated | +| RateLimiter | DEBUG | Rate check passed (key, remaining) | +| RateLimiter | NOTICE | Rate limit exceeded (key, limit, retry-after) | +| Migrator | INFO | Migration applied / rolled back (file, elapsed ms) | +| Migrator | WARNING | Checksum mismatch (file, expected, actual) | +| Migrator | ERROR | Migration failed (file, error) | + +**What the framework never logs:** session IDs, auth tokens, passwords, request/response bodies. + +**Exceptions are already handled.** Glitch `LogReporter` logs exceptions at ERROR/CRITICAL via channel routing. The kernel logs lifecycle; Glitch logs failures — no duplication. + +**Bring your own logger.** `Bootstrap\Logger` binds `LoggerInterface` to `QuillLogger` with a `has()` guard. If the app registers a custom PSR-3 implementation before `Bootstrap\Logger` runs, the framework respects it. + +--- + ## Conventions that hold it all together Arcanum's small mental model comes from a handful of conventions that show up everywhere. Learn these once and most of the framework explains itself. diff --git a/PLAN.md b/PLAN.md index 4c68f9f..e0b3416 100644 --- a/PLAN.md +++ b/PLAN.md @@ -8,15 +8,179 @@ These are the highest-impact items from the backlog. Each needs to be broken into a walkable checklist before work begins. -1. **Logging instrumentation** — The only pre-1.0 blocker. The framework is silent in production. Inject `?LoggerInterface` progressively across the HTTP lifecycle first (routing → dispatch → render → response), then expand to auth, cache, throttle, migrations. Log *decisions*, not *data*. Null means silent — no performance cost when logging is disabled. +1. **Logging instrumentation** — details in checklist below. +2. **Todo App dogfood** — details in checklist below. -2. **Todo App dogfood** — Build a full Todo app using the starter app. SQLite via Forge, Vault caching, auth with sessions, Tailwind + htmx front-end. Full CRUD, task lists, completion toggling, filtering. Then write a retrospective: pain points, what worked, friction in the DX, missing features. The retrospective feeds back into new plan items. This is how we find what we can't see from the framework side. +3. **Hyper README** — details in checklist below. +4. **PSR-18 HTTP Client** — details in checklist below. +5. **Integration test coverage** — details in checklist below. -3. **Hyper README** — The only core package without a README. Document PSR-7 message classes, response renderers, exception renderers, format registry, file uploads, URI handling. Quick win, high credibility impact. +--- + +### Logging instrumentation + +Pre-1.0 blocker. The framework is silent in production — no request lifecycle, no routing decisions, no auth outcomes. Fix this by injecting `?LoggerInterface $logger = null` progressively across the stack, starting with the HTTP lifecycle and expanding outward. + +**Principles:** + +- **Log decisions, not data.** "Route resolved via convention" yes; request body, session contents, SQL results no. **Never log:** session IDs, auth tokens, passwords, request/response bodies. Rate-limit keys (typically IPs) are the app's responsibility to hash or truncate for GDPR — the framework logs the key it's given. +- **Null means silent.** `$this->logger?->method()` short-circuits when no logger is configured — zero allocation, zero cost. +- **One INFO line per request.** The "access log" is a single INFO entry when the request completes (method, path, status code). Everything else is DEBUG or NOTICE. +- **Correlate with a correlation ID.** Generate a short random ID at the start of `handle()` and include it as `'correlation_id'` in every log record's extra data via a Monolog processor. Without this, interleaved DEBUG lines from concurrent requests are useless. Implement as a `CorrelationProcessor` registered in Bootstrap\Logger so it applies to all channels automatically. +- **Exceptions are already handled.** Glitch `LogReporter` already logs exceptions at ERROR/CRITICAL via channel routing. Don't duplicate — the kernel logs lifecycle, Glitch logs failures. +- **Apps can bring their own logger.** The `LoggerInterface` binding uses a `has()` guard — if the app registered a custom PSR-3 implementation before Bootstrap\Logger runs, the framework respects it. +- **All code changes must pass `composer check`.** Every item must pass cs-fix, cs-check, phpstan, and phpunit before commit. + +**Log levels:** + +| Level | When | Examples | +|-------|------|---------| +| DEBUG | Resolution/lookup details, dev troubleshooting | Route resolved, session loaded, no identity, dispatching handler, command resolved | +| INFO | Lifecycle milestones, the "access log" | Request handled (status), command completed (exit code), migration applied, identity resolved | +| NOTICE | Noteworthy but expected conditions | Rate limit exceeded, session regenerated/invalidated, 405 method not allowed, 406 not acceptable | +| WARNING | Integrity issues | Migration checksum mismatch | +| ERROR | Runtime failures | Migration execution failed | + +**Architecture notes:** + +- **Factory-registered classes** (HttpRouter, AuthMiddleware): constructed with `new` in bootstrap closures, but the closures execute lazily at request time — after Logger bootstraps. Update each factory to resolve and pass the logger from the container. +- **PSR-15 middleware** (SessionMiddleware): resolved from the container by `HttpMiddleware` at dispatch time. Adding `?LoggerInterface` to the constructor is sufficient — Codex auto-wires it. +- **Conveyor Progressions** (AuthorizationGuard, ValidationGuard): constructed with `new` in Routing/CliRouting bootstrappers before Logger runs. Their rejections surface as exceptions that Glitch already reports. Skip — low logging value, high wiring cost. +- **Kernels** (HyperKernel, RuneKernel): constructed before the container exists. Resolve the logger lazily from the container after bootstrap. + +#### Checklist + +- [x] **Bootstrap\Logger — bind `LoggerInterface` + correlation processor** — Add `$container->service(LoggerInterface::class, QuillLogger::class)` with a `has()` guard so apps can bring their own PSR-3 implementation. Register a `CorrelationProcessor` (generic Monolog processor) that adds `'correlation_id'` to every log record's extra (generated once per kernel handle cycle). This is the prerequisite for all Codex auto-wiring of `?LoggerInterface` params and for correlating log lines across concurrent requests. +- [x] **HyperKernel + RuneKernel — lifecycle logging** — Resolve logger from container after bootstrap. Generate request/command ID and set on processor. HyperKernel: DEBUG `Request received` (method, path) at handle start; INFO `Request handled` (method, path, status) after response built. RuneKernel: DEBUG `Command received` (name) at handle start; INFO `Command completed` (name, exit code) after dispatch. Tests with mock logger via `expects()`. +- [x] **HttpRouter — route resolution logging** — Add `?LoggerInterface $logger = null` to constructor. Update factory in Bootstrap\Routing to pass logger from container. DEBUG `Route resolved` (type: custom/page/convention, DTO class, format). DEBUG `Route not found` before 404. NOTICE `Method not allowed` (path, method, allowed methods) before 405. NOTICE `Format not acceptable` (format, allowed) before 406. Tests for each log path + null logger. +- [x] **RouteDispatcher — dispatch logging** — Add `?LoggerInterface $logger = null` to constructor. DEBUG `Dispatching` (DTO class, handler prefix, before/after middleware count). Tests with mock logger. +- [x] **CliRouter — command routing logging** — Add `?LoggerInterface $logger = null` to constructor. Update factory in Bootstrap\CliRouting to pass logger. DEBUG `Command resolved` (type, DTO class). DEBUG `Command not found` (input name, suggestions if any). Tests. +- [x] **AuthMiddleware — authentication logging** — Add `?LoggerInterface $logger = null` to constructor. Update factory in Bootstrap\Auth to pass logger. INFO `Identity resolved` (guard type: session/token/composite — never identity details, never tokens). DEBUG `No identity resolved` (unauthenticated, not an error). Tests. +- [x] **SessionMiddleware — session lifecycle logging** — Add `?LoggerInterface $logger = null` to constructor (Codex auto-wires, no factory change needed). DEBUG `Session started` (new vs loaded — never log session ID). DEBUG `Session saved`. NOTICE `Session regenerated`. NOTICE `Session invalidated`. Tests. +- [x] **RateLimiter — throttle logging** — Add `?LoggerInterface $logger = null` to constructor. NOTICE `Rate limit exceeded` (key, limit, retry-after). DEBUG `Rate check passed` (key, remaining). Tests. +- [x] **Migrator — migration logging** — Add `?LoggerInterface $logger = null` to constructor. INFO `Migration applied` (filename, direction, elapsed ms). INFO `Migration rolled back` (filename, elapsed ms). WARNING `Checksum mismatch` (filename, expected, actual). ERROR `Migration failed` (filename, error). Tests. +- [x] **Harmonize existing log sites** — Review and align the three existing logging patterns: MiddlewareBus (debug-gated `->warning()`), TemplateEngine (null-safe `?->warning()`), Bootstrap\Routing (`has()` + explicit get). Standardize on null-safe `?->` with consistent context keys. Note: the starter app's `RequestLogger` listener becomes redundant once kernel lifecycle logging lands — document this in the starter app's README or remove the listener. +- [x] **COMPENDIUM.md + Quill README — document logging** — Add a "Framework logging" section to the COMPENDIUM describing what the framework logs, at what levels, the request ID correlation mechanism, and how to bring your own PSR-3 logger. Update the Quill README if needed. + +### Todo App dogfood + +Two parallel builds of the same Todo app, each from a different starting point. The Todo app is the vehicle; the journals and retrospective are the deliverables. **No framework changes unless there's a complete blocker** — record friction, don't fix it mid-flight. + +**The Todo app (same features both times):** + +- SQLite via Forge — `users`, `task_lists`, `tasks` tables via migrations +- Session auth — login page, session guard, `#[RequiresAuth]` on todo routes +- Task list CRUD — create, delete lists +- Task CRUD — add, toggle completion, delete tasks +- htmx front-end — no full page reloads for task operations, `ClientBroadcast` for count refresh +- Filter tasks — all / active / completed via htmx +- Vault caching — task counts per list, invalidated on mutations +- Tailwind styling, validation feedback on forms + +**What to record in each `JOURNAL.md`:** + +- Every step taken, in order +- Rough time per step +- Pain points — unclear docs, missing features, confusing conventions, boilerplate +- Wins — things that "just worked," elegant patterns, small mental model +- Blockers — framework bugs, missing functionality, workarounds needed +- Missing scaffolding — `make:*` commands that should exist but don't (e.g., `make:seed`, `make:event`, `make:model`) +- Config mysteries — settings that were hard to discover or required reading framework source +- Error messages — which ones helped, which ones didn't +- Testing DX — was `TestKernel` / `HttpTestSurface` / `Factory` obvious? Did `actingAs()` work? What was missing? +- CSRF experience — did `CsrfMiddleware` + `{{ csrf }}` + htmx JS shim "just work" or require debugging? + +#### Checklist + +- [ ] **Build A: clone starter** — Clone `../arcanum/` into `../todo-from-starter/`. Strip the guestbook domain, welcome page helpers, and demo-specific code. Keep the infrastructure (kernels, config, layout, bootstrap, migrations setup). Record every step in `JOURNAL.md`. +- [ ] **Build A: build the todo app** — Schema, auth, Forge models, commands, queries, htmx templates, filtering, caching. Note the data seeding problem: migrations are SQL-only, so seeding a user with `password_hash()` requires a workaround (pre-computed hash in SQL, PHP seed script, or custom CLI command). Journal whatever solution you use and whether the framework should ship a seeder mechanism. Write a few tests using `TestKernel` / `HttpTestSurface` / `Factory` to exercise the Testing package's DX. Commit working features incrementally. Continue journaling: every pain point, every win, every workaround, every "I had to read framework source to figure this out." +- [ ] **Build B: from scratch** — New directory `../todo-from-scratch/`. `composer init`, `composer require arcanum-org/framework` (first test: is the package discoverable? is it on Packagist? does the README explain installation?). Create `public/index.php`, `bin/arcanum`, config files, kernels, `.env`, directory structure — everything from zero. Journal every step, especially: which config files were needed and how you discovered the required keys, what happened when a config file was missing (helpful error or cryptic crash?), which bootstrappers were required and in what order. +- [ ] **Build B: build the todo app** — Same features as Build A, including tests with the Testing package. Journal everything, especially: which steps were harder without the starter's scaffolding, which conventions took trial-and-error to discover, which error messages pointed to the fix vs. which were opaque. +- [ ] **Retrospective** — Compare both journals. Write `RETROSPECTIVE.md` (in this repo) covering: (1) framework features that worked well, (2) framework features that were hard to use or missing, (3) DX gaps — missing docs, unclear conventions, missing scaffolding, unhelpful errors, (4) ecosystem gaps — what a new user can't figure out without reading framework internals, (5) Testing package DX — was the test harness usable, what was missing. Extract concrete items and add to PLAN.md. + +### Hyper README + +The only core package without a README. Hyper is the biggest package — PSR-7 messages, URI handling, file uploads, response renderers, exception renderers, format registry, middleware chain, lifecycle events, server adapter. The audience is a junior developer exploring the framework to learn; lead with "what happens when an HTTP request arrives" and work outward from there. + +#### Sections to cover + +1. **What Hyper does** — one paragraph: PSR-7 HTTP messages, response rendering, middleware chain, lifecycle events. Hyper handles the HTTP boundary so the rest of the framework stays transport-agnostic. +2. **"You probably won't import this"** — Set expectations immediately: in most Arcanum apps, handlers never touch Hyper directly. You return a DTO, and the rendering pipeline produces the HTTP response. Hyper matters when you're writing middleware, custom renderers, or debugging the request lifecycle. This prevents a junior dev from thinking they need to construct Response objects in handlers. +3. **The request journey** — visual flow from raw PHP superglobals → `Server` → `ServerRequest` → middleware → handler → `ResponseRenderer` → `Response` → sent to client. Anchor the reader before diving into classes. Call out `Server` explicitly — it's what `public/index.php` actually uses to parse the request. +4. **PSR-7 messages** — Request, ServerRequest, Response, Message, Headers. Show how to read headers, query params, parsed body. Explain the immutable `with*()` pattern for anyone who hasn't seen PSR-7 before. +5. **URI** — URI class parses and builds URIs. Show `new URI('https://...')`, the `with*()` methods for each component. Mention the component value objects (Scheme, Host, Path, etc.) exist but most code just uses `URI` directly. +6. **Status codes** — The `StatusCode` enum and why Arcanum uses it instead of raw integers. Show `StatusCode::NotFound`, `$status->reason()`. Link to the COMPENDIUM's "HTTP status codes are part of the API" philosophy. +7. **File uploads** — `UploadedFile`, `UploadedFiles::fromSuperGlobal()`. Show how to access files in a handler. Mention the `Error` enum for upload error codes. +8. **Response renderers** — The 6 renderers (Json, Html, PlainText, Markdown, Csv, Empty). How `FormatRegistry` maps URL extensions to renderers. How template-based renderers compose `TemplateResolver` + `TemplateEngine` (link to Shodo README). The status-specific template resolution chain. Show a handler returning data and the renderer turning it into a response. +9. **Exception renderers** — `JsonExceptionResponseRenderer`, `HtmlExceptionResponseRenderer`, `ValidationExceptionRenderer` (decorator that adds 422-specific handling). How exceptions become proper error responses. Debug vs production mode. The htmx fragment fallback for error templates. Link to Glitch README. +10. **Format registry** — How `FormatRegistry` works, how 406 Not Acceptable happens, how to register custom formats in `config/formats.php`. +11. **Middleware** — `HttpMiddleware` builds a PSR-15 middleware chain. Show the onion model. `CallableHandler` wraps closures as handlers. The `Options` middleware auto-responds to OPTIONS with the `Allow` header. +12. **Lifecycle events** — `RequestReceived` (mutable — listeners can enrich the request), `RequestHandled` / `RequestFailed` / `ResponseSent` (read-only). Show a listener example. Link to Echo README. +13. **Server and ServerAdapter** — `Server` composes the `PHPServerAdapter` to build PSR-7 objects from `$_SERVER`, `$_GET`, `$_POST`, `$_FILES`, `$_COOKIE`. Explain why the adapter exists (testability — swap for a mock in tests). This is the bridge between PHP's superglobals and the PSR-7 world. +14. **#[HttpOnly] attribute** — marks DTOs as HTTP-only, rejected in CLI by TransportGuard. + +#### Checklist + +- [ ] **Hyper README — request journey and PSR-7** — Sections 1–7: overview, "you probably won't import this" framing, request flow diagram with Server callout, PSR-7 messages, URI, status codes, file uploads. Cross-link to Shodo, Glitch, Echo READMEs where referenced. Enough for a reader to understand how requests arrive and what they look like inside the framework. +- [ ] **Hyper README — rendering and middleware** — Sections 8–14: response renderers, exception renderers (including ValidationExceptionRenderer decorator), format registry, middleware chain, lifecycle events, server + adapter, #[HttpOnly]. Cross-link to related package READMEs. Completes the "response side" of the journey. + +### PSR-18 HTTP Client + +Any real app needs outgoing HTTP requests (APIs, OAuth, webhooks). Wrap an established library behind PSR-18 `ClientInterface` and provide PSR-17 factories over Hyper's existing PSR-7 classes. Ship a test mock so apps can assert outgoing calls without hitting the network. + +**Architecture decisions:** + +- **PSR-17 factories over Hyper classes.** `RequestFactory` composes `Message` + `Request` + `URI`. `ResponseFactory` composes `Message` + `Response`. `UriFactory` delegates to `new URI($string)`. `StreamFactory` needs a PSR-7 `StreamInterface` implementation — River's `Stream` has every required method but doesn't declare `implements StreamInterface`. **Decision: extend River\Stream to implement the interface.** One `implements` addition makes all of River PSR-7 compatible with no adapter overhead. +- **PSR-18 client wraps Guzzle, but Guzzle is optional.** Guzzle is currently a dev/transitive dependency, not a production one. The framework must not force every app to install Guzzle. Instead: `composer.json` adds Guzzle as a `suggest`, `Bootstrap\HttpClient` checks `class_exists(GuzzleHttp\Client::class)` before registering. Apps that need outgoing HTTP do `composer require guzzlehttp/guzzle`. Apps that don't pay nothing. The wrapper maps Guzzle exceptions to PSR-18 `NetworkException`/`RequestException`. +- **Convenience methods alongside PSR-18.** `sendRequest(RequestInterface)` is the PSR-18 contract. The wrapper also provides `get($url, $headers)`, `post($url, $body, $headers)`, etc. that build the request internally — less verbose for common cases. +- **TestClient for app testing.** Records outgoing requests, returns pre-configured responses. Registered in the container during tests. Same pattern as `FrozenClock` and `ArrayDriver` — deterministic, no side effects. +- **Lives at `src/Hyper/Client/`** as a sub-namespace of Hyper, since it builds on the same PSR-7 classes. + +**Security:** + +- **TLS verification must default to on.** The Guzzle wrapper must never disable SSL verification by default. If `config/http.php` exposes a `verify` option, it defaults to `true`. The README warns against disabling in production. +- **Sensitive header scrubbing in logs.** When logging integration lands, outgoing request logging must strip `Authorization`, `Cookie`, `X-Api-Key`, and other sensitive headers from log context by default. Configurable blacklist. + +#### Checklist + +- [ ] **River\Stream — implement `StreamInterface`** — Add `implements StreamInterface` to `Flow\River\Stream`. It already has every method; this is a declaration, not a rewrite. Adjust any signature mismatches. Update River tests. This unblocks PSR-17 StreamFactory. +- [ ] **PSR-17 factories** — `RequestFactory`, `ResponseFactory`, `UriFactory`, `StreamFactory` over Hyper's existing PSR-7 classes. Add `psr/http-factory` as a direct dependency. Tests for each factory. +- [ ] **PSR-18 client** — `HttpClient implements ClientInterface` wrapping Guzzle. Constructor takes Guzzle `ClientInterface` (or builds a default if Guzzle is installed). Convenience methods: `get()`, `post()`, `put()`, `patch()`, `delete()`. Maps Guzzle exceptions to PSR-18 `NetworkException`/`RequestException`. Add `psr/http-client` as a direct dependency; add `guzzlehttp/guzzle` as a `suggest`. Config via `config/http.php` (base_uri, timeout, headers, verify defaults to `true`). Tests with Guzzle mock handler. +- [ ] **TestClient** — `TestClient implements ClientInterface` for app tests. `addResponse(ResponseInterface)` queues responses. `assertSent(callable)` checks recorded requests. `assertNothingSent()`. Register in container when `TestKernel` is used. Tests. +- [ ] **Bootstrap registration** — `Bootstrap\HttpClient` registers factories and client in the container. PSR-17 interfaces bound to Hyper factories. PSR-18 `ClientInterface` bound to the Guzzle wrapper only if `class_exists(GuzzleHttp\Client::class)` — skip gracefully otherwise. `has()` guards so apps can bring their own. Sensitive header scrubbing list for future logging integration (`Authorization`, `Cookie`, `X-Api-Key`). +- [ ] **README** — What it does, when to use it, sending requests (PSR-18 and convenience methods), handling responses, testing with TestClient, configuration, TLS verification warning, swapping implementations. + +### Integration test coverage + +Only 2 integration tests exist today (`CqrsLifecycleTest`, `HelperResolutionTest`). Unit tests miss interaction bugs: discovery ordering, bootstrap sequencing, round-trip rendering, lifecycle event flow. `TestKernel` already provides `HttpTestSurface` and `CliTestSurface` — expanding coverage is cheap. This is also a long-tail principle: every new feature should land with at least one integration test. + +**What exists today:** +- `CqrsLifecycleTest` — HTTP request → routing → hydration → dispatch → render (JSON/CSV/HTML), command 204/201, per-route middleware. +- `HelperResolutionTest` — global + domain-scoped helpers through real bootstrappers. +- `TestKernel` — shared container with FrozenClock, ArrayDriver cache, ActiveIdentity, lazy HTTP/CLI surfaces, `actingAs()`. + +**What's missing:** + +| Gap | Why it matters | +|-----|----------------| +| CLI lifecycle | Zero CLI integration tests. Routing, dispatch, output formatting, exit codes untested end-to-end. | +| htmx rendering | HX-Request header → fragment extraction is a key user-facing path with no integration test. | +| Error responses | 404, 405, 406, 422, 500 across JSON and HTML formats — only unit-tested in isolation. | +| Session + auth | Session middleware → auth middleware → AuthorizationGuard flow never tested as a chain. | +| Lifecycle events | Events fire in unit tests, but never verified in a full middleware → handler → render pass. | +| Template rendering | HTTP request → TemplateResolver → TemplateCompiler → TemplateEngine → response never tested end-to-end. | + +**Fixture convention:** Integration test fixtures (DTOs, handlers, templates, middleware) live in `tests/Integration/Fixture/`, mirroring the pattern established by `CqrsLifecycleTest`. Some tests (SessionAuth, Template) require real middleware chains — use `TestKernel` with selective bootstrapper setup or manual wiring as needed. -4. **PSR-18 HTTP Client** — Any real app needs outgoing HTTP requests (APIs, OAuth, webhooks). Wrap an established library, implement PSR-18 `ClientInterface` and PSR-17 factories over Hyper's existing PSR-7 classes. Bootstrap registration, testing mock, logging integration. +#### Checklist -5. **Integration test coverage** — Only 2 integration tests exist today (`CqrsLifecycleTest`, `HelperResolutionTest`). Unit tests miss interaction bugs: discovery ordering, bootstrap sequencing, round-trip rendering, lifecycle event flow. TestKernel already exists — expanding coverage is cheap. Long-tail effort: every new feature should land with at least one integration test. +- [ ] **CliIntegrationTest** — CLI routing → hydration → dispatch → output rendering → exit codes. Cover: convention-based command, query with formatted output, built-in command (`list`), unknown command (error + suggestion), `--help` flag. +- [ ] **HtmxIntegrationTest** — Request with `HX-Request` header → fragment rendering (content section only, no layout). Cover: `HX-Target` → element-by-id extraction, `ClientBroadcast` → `HX-Trigger` header on response, `Vary: HX-Request` header. +- [ ] **ErrorResponseIntegrationTest** — Full error lifecycle across formats. Cover: 404 (no route), 405 (wrong method → correct Allow header), 406 (unsupported format), 422 (validation failure → field errors), 500 (unhandled exception). Verify both JSON and HTML renderers produce correct status codes and content. +- [ ] **SessionAuthIntegrationTest** — Session start → identity set → AuthorizationGuard enforcement → CSRF validation. Cover: unauthenticated request to `#[RequiresAuth]` → 401, authenticated request → passes, wrong role → 403, policy check with DTO data, CSRF token round-trip (session → form → validation). This test requires SessionMiddleware + AuthMiddleware + CsrfMiddleware + the Conveyor pipeline wired together — document the setup pattern for future complex integration tests. +- [ ] **MiddlewareOrderIntegrationTest** — Verify middleware executes in registered order. Register middleware A, B, C; verify execution order is A → B → C → handler → C → B → A (onion model). Catches ordering bugs that unit tests miss. +- [ ] **LifecycleEventIntegrationTest** — Verify all events fire in correct order during a full HTTP request. Cover: `RequestReceived` (mutable — verify listener can enrich request), `RequestHandled` (verify request + response pair), `RequestFailed` (verify exception captured), `ResponseSent` (verify fires in terminate). Parallel test for CLI events (`CommandReceived`, `CommandHandled`, `CommandFailed`, `CommandCompleted`). +- [ ] **TemplateRenderIntegrationTest** — HTTP request → template resolution → compilation → rendering with helpers. Cover: co-located template found, layout extends, helper calls resolve, status-specific template (422 error template). --- diff --git a/src/Atlas/CliRouter.php b/src/Atlas/CliRouter.php index 099cfc9..845a7cc 100644 --- a/src/Atlas/CliRouter.php +++ b/src/Atlas/CliRouter.php @@ -5,6 +5,7 @@ namespace Arcanum\Atlas; use Arcanum\Rune\Input; +use Psr\Log\LoggerInterface; /** * Maps CLI input to Routes using the convention system. @@ -31,6 +32,7 @@ public function __construct( private readonly ConventionResolver $resolver, private readonly CliRouteMap|null $routeMap = null, private readonly string $defaultFormat = 'cli', + private readonly ?LoggerInterface $logger = null, ) { } @@ -54,6 +56,10 @@ public function resolve(object $input): Route // Custom routes take priority — check full command name first. if ($this->routeMap !== null && $this->routeMap->has($command)) { $route = $this->routeMap->resolve($command, $format); + $this->logger?->debug('Command resolved', [ + 'type' => 'custom', + 'dto' => $route->dtoClass, + ]); return $input->hasFlag('help') ? $route->withHelp() : $route; } @@ -100,9 +106,16 @@ public function resolve(object $input): Route ); if (class_exists($route->dtoClass) || class_exists($route->dtoClass . 'Handler')) { + $this->logger?->debug('Command resolved', [ + 'type' => 'convention', + 'dto' => $route->dtoClass, + ]); return $input->hasFlag('help') ? $route->withHelp() : $route; } + $this->logger?->debug('Command not found', [ + 'input' => $command, + ]); throw $this->buildNotFoundError($command, $typeNamespace, $path, $format); } diff --git a/src/Atlas/HttpRouter.php b/src/Atlas/HttpRouter.php index 81995a5..6bd908b 100644 --- a/src/Atlas/HttpRouter.php +++ b/src/Atlas/HttpRouter.php @@ -8,6 +8,7 @@ use Arcanum\Glitch\HttpException; use Arcanum\Hyper\StatusCode; use Psr\Http\Message\ServerRequestInterface; +use Psr\Log\LoggerInterface; final class HttpRouter implements Router { @@ -25,6 +26,7 @@ public function __construct( private readonly RouteMap|null $routeMap = null, private readonly PageResolver|null $pages = null, private readonly string $defaultFormat = 'json', + private readonly ?LoggerInterface $logger = null, ) { } @@ -91,11 +93,22 @@ public function resolve(object $input): Route ); $this->assertFormatAllowed($route); + $this->logger?->debug('Route resolved', [ + 'type' => 'custom', + 'dto' => $route->dtoClass, + 'format' => $route->format, + ]); + return $route; } if ($this->pages !== null && $this->pages->has($cleanPath)) { if ($method !== 'GET') { + $this->logger?->notice('Method not allowed', [ + 'path' => $cleanPath, + 'method' => $method, + 'allowed' => self::QUERY_METHODS, + ]); throw new MethodNotAllowed(self::QUERY_METHODS); } @@ -105,6 +118,12 @@ public function resolve(object $input): Route ); $this->assertFormatAllowed($route); + $this->logger?->debug('Route resolved', [ + 'type' => 'page', + 'dto' => $route->dtoClass, + 'format' => $route->format, + ]); + return $route; } @@ -117,12 +136,24 @@ public function resolve(object $input): Route if (class_exists($route->dtoClass)) { $this->assertFormatAllowed($route); + $this->logger?->debug('Route resolved', [ + 'type' => 'convention', + 'dto' => $route->dtoClass, + 'format' => $route->format, + ]); + return $route; } // If the DTO class doesn't exist but the handler does, allow it — // the kernel will create a dynamic Command or Query DTO. if (class_exists($route->dtoClass . 'Handler')) { + $this->logger?->debug('Route resolved', [ + 'type' => 'convention', + 'dto' => $route->dtoClass, + 'format' => $route->format, + ]); + return $route; } @@ -150,6 +181,10 @@ private function assertFormatAllowed(Route $route): void $allowed = $attrs[0]->newInstance(); if (!in_array($route->format, $allowed->formats, true)) { + $this->logger?->notice('Format not acceptable', [ + 'format' => $route->format, + 'allowed' => $allowed->formats, + ]); throw new HttpException( StatusCode::NotAcceptable, sprintf( @@ -185,9 +220,16 @@ private function throwForMissingClass( ); if (class_exists($alternateRoute->dtoClass) || class_exists($alternateRoute->dtoClass . 'Handler')) { + $this->logger?->notice('Method not allowed', [ + 'path' => $path, + 'method' => $method, + 'allowed' => $alternateMethods, + ]); throw new MethodNotAllowed($alternateMethods); } + $this->logger?->debug('Route not found', ['path' => $path]); + throw (new HttpException( StatusCode::NotFound, sprintf('No route found for path "%s".', $path), diff --git a/src/Auth/AuthMiddleware.php b/src/Auth/AuthMiddleware.php index f4b5e17..c3b6ef4 100644 --- a/src/Auth/AuthMiddleware.php +++ b/src/Auth/AuthMiddleware.php @@ -8,6 +8,7 @@ use Psr\Http\Message\ServerRequestInterface; use Psr\Http\Server\MiddlewareInterface; use Psr\Http\Server\RequestHandlerInterface; +use Psr\Log\LoggerInterface; /** * PSR-15 middleware that resolves the authenticated Identity. @@ -24,6 +25,7 @@ final class AuthMiddleware implements MiddlewareInterface public function __construct( private readonly Guard $guard, private readonly ActiveIdentity $activeIdentity, + private readonly ?LoggerInterface $logger = null, ) { } @@ -33,15 +35,38 @@ public function process(ServerRequestInterface $request, RequestHandlerInterface if ($identity !== null) { $this->activeIdentity->set($identity); + $this->logger?->info('Identity resolved', [ + 'guard' => $this->resolvedGuardType(), + ]); if ($this->isTokenAuthenticated()) { $request = $request->withAttribute('auth.token_authenticated', true); } + } else { + $this->logger?->debug('No identity resolved'); } return $handler->handle($request); } + private function resolvedGuardType(): string + { + if ($this->guard instanceof CompositeGuard) { + $last = $this->guard->lastResolvedGuard(); + return $last !== null ? $this->guardName($last) : 'composite'; + } + + return $this->guardName($this->guard); + } + + private function guardName(Guard $guard): string + { + $class = get_class($guard); + $pos = strrpos($class, '\\'); + $short = $pos !== false ? substr($class, $pos + 1) : $class; + return str_replace('Guard', '', $short) ?: $short; + } + private function isTokenAuthenticated(): bool { if ($this->guard instanceof TokenGuard) { diff --git a/src/Flow/Conveyor/MiddlewareBus.php b/src/Flow/Conveyor/MiddlewareBus.php index 5770acd..4f8dc4b 100644 --- a/src/Flow/Conveyor/MiddlewareBus.php +++ b/src/Flow/Conveyor/MiddlewareBus.php @@ -19,8 +19,7 @@ class MiddlewareBus implements Bus private bool $hasValidationGuard = false; /** - * @param bool $debug When true, log a warning when a prefixed handler - * is not found and the bus falls back to the unprefixed handler. + * @param bool $debug Reserved for future use. */ public function __construct( protected ContainerInterface $container, @@ -98,13 +97,10 @@ protected function handlerFor(object $object, string $prefix = ''): callable return $this->container->get($prefixedName); } - if ($this->debug && $this->logger !== null) { - $this->logger->warning(sprintf( - 'Handler "%s" not found, falling back to "%s".', - $prefixedName, - $this->handlerNameFor($object), - )); - } + $this->logger?->warning('Handler not found, falling back to unprefixed', [ + 'prefixed' => $prefixedName, + 'fallback' => $this->handlerNameFor($object), + ]); } $handlerName = $this->handlerNameFor($object); @@ -166,17 +162,19 @@ private function warnIfValidationMissing(object $object): void return; } - $message = sprintf( - 'DTO "%s" has validation rules but no ValidationGuard is registered. ' - . 'Validation will not run. Register ValidationGuard as before-middleware on the bus.', - get_class($object), - ); + $dtoClass = get_class($object); if ($this->debug) { - throw new \RuntimeException($message); + throw new \RuntimeException(sprintf( + 'DTO "%s" has validation rules but no ValidationGuard is registered. ' + . 'Validation will not run. Register ValidationGuard as before-middleware on the bus.', + $dtoClass, + )); } - $this->logger?->warning($message); + $this->logger?->warning('ValidationGuard missing for DTO with rules', [ + 'dto' => $dtoClass, + ]); } /** diff --git a/src/Forge/Migration/Migrator.php b/src/Forge/Migration/Migrator.php index 5c86f52..9ea37be 100644 --- a/src/Forge/Migration/Migrator.php +++ b/src/Forge/Migration/Migrator.php @@ -5,6 +5,7 @@ namespace Arcanum\Forge\Migration; use Arcanum\Forge\Connection; +use Psr\Log\LoggerInterface; /** * Orchestrates database migrations: running, rolling back, and reporting status. @@ -28,6 +29,7 @@ public function __construct( private readonly Connection $connection, private readonly MigrationRepository $repository, private readonly string $migrationsPath, + private readonly ?LoggerInterface $logger = null, ) { $this->parser = new MigrationParser(); } @@ -46,9 +48,14 @@ public function migrate(?callable $onMigrate = null): MigrationResult $applied = $this->repository->applied(); // Checksum validation — halt on any mismatch. - $checksumError = $this->validateChecksums($files, $applied); - if ($checksumError !== null) { - return new MigrationResult([], [$checksumError]); + $checksumMismatch = $this->validateChecksums($files, $applied); + if ($checksumMismatch !== null) { + $this->logger?->warning('Checksum mismatch', [ + 'file' => $checksumMismatch['file'], + 'expected' => $checksumMismatch['expected'], + 'actual' => $checksumMismatch['actual'], + ]); + return new MigrationResult([], [$checksumMismatch['error']]); } $pending = $this->filterPending($files, $applied); @@ -65,12 +72,21 @@ public function migrate(?callable $onMigrate = null): MigrationResult try { $this->executeMigration($file, 'up'); } catch (MigrationFailed $e) { + $this->logger?->error('Migration failed', [ + 'file' => $file->filename, + 'error' => $e->getMessage(), + ]); return new MigrationResult($ran, [$e->getMessage()]); } $elapsedMs = (hrtime(true) - $start) / 1_000_000; $ran[] = $file->filename; + $this->logger?->info('Migration applied', [ + 'file' => $file->filename, + 'elapsed_ms' => round($elapsedMs, 2), + ]); + if ($onMigrate !== null) { $onMigrate($file, $elapsedMs); } @@ -121,12 +137,21 @@ public function rollback(int $steps = 1, ?callable $onRollback = null): Migratio try { $this->executeRollback($file); } catch (MigrationFailed $e) { + $this->logger?->error('Migration failed', [ + 'file' => $file->filename, + 'error' => $e->getMessage(), + ]); return new MigrationResult($ran, [$e->getMessage()]); } $elapsedMs = (hrtime(true) - $start) / 1_000_000; $ran[] = $file->filename; + $this->logger?->info('Migration rolled back', [ + 'file' => $file->filename, + 'elapsed_ms' => round($elapsedMs, 2), + ]); + if ($onRollback !== null) { $onRollback($file, $elapsedMs); } @@ -208,8 +233,9 @@ private function scanFiles(): array * * @param list $files * @param array $applied + * @return array{file: string, expected: string, actual: string, error: string}|null */ - private function validateChecksums(array $files, array $applied): ?string + private function validateChecksums(array $files, array $applied): ?array { $filesByVersion = []; foreach ($files as $file) { @@ -223,14 +249,19 @@ private function validateChecksums(array $files, array $applied): ?string $file = $filesByVersion[$record->version]; if ($file->checksum !== $record->checksum) { - return sprintf( - 'Migration "%s" has been modified after it was applied ' - . '(expected checksum %s, got %s). ' - . 'Applied migrations must not be edited.', - $record->filename, - $record->checksum, - $file->checksum, - ); + return [ + 'file' => $record->filename, + 'expected' => $record->checksum, + 'actual' => $file->checksum, + 'error' => sprintf( + 'Migration "%s" has been modified after it was applied ' + . '(expected checksum %s, got %s). ' + . 'Applied migrations must not be edited.', + $record->filename, + $record->checksum, + $file->checksum, + ), + ]; } } diff --git a/src/Ignition/Bootstrap/Auth.php b/src/Ignition/Bootstrap/Auth.php index 4a25865..fa5623e 100644 --- a/src/Ignition/Bootstrap/Auth.php +++ b/src/Ignition/Bootstrap/Auth.php @@ -80,7 +80,11 @@ function () use ($container): AuthMiddleware { $guard = $container->get(Guard::class); /** @var ActiveIdentity $activeIdentity */ $activeIdentity = $container->get(ActiveIdentity::class); - return new AuthMiddleware($guard, $activeIdentity); + $logger = $container->has(\Psr\Log\LoggerInterface::class) + ? $container->get(\Psr\Log\LoggerInterface::class) + : null; + /** @var ?\Psr\Log\LoggerInterface $logger */ + return new AuthMiddleware($guard, $activeIdentity, $logger); }, ); } diff --git a/src/Ignition/Bootstrap/CliRouting.php b/src/Ignition/Bootstrap/CliRouting.php index d17c5b9..54c730b 100644 --- a/src/Ignition/Bootstrap/CliRouting.php +++ b/src/Ignition/Bootstrap/CliRouting.php @@ -119,8 +119,13 @@ private function registerRouter(Application $container, Configuration $config): $container->instance(CliRouteMap::class, $routeMap); - $container->factory(Router::class, function () use ($resolver, $routeMap) { - return new CliRouter($resolver, $routeMap); + $container->factory(Router::class, function () use ($container, $resolver, $routeMap) { + $logger = $container->has(\Psr\Log\LoggerInterface::class) + ? $container->get(\Psr\Log\LoggerInterface::class) + : null; + + /** @var ?\Psr\Log\LoggerInterface $logger */ + return new CliRouter($resolver, $routeMap, logger: $logger); }); } diff --git a/src/Ignition/Bootstrap/Logger.php b/src/Ignition/Bootstrap/Logger.php index 2ab3c7f..0a4dff4 100644 --- a/src/Ignition/Bootstrap/Logger.php +++ b/src/Ignition/Bootstrap/Logger.php @@ -9,6 +9,7 @@ use Arcanum\Quill\Handler; use Arcanum\Quill\Logger as QuillLogger; use Arcanum\Quill\Channel; +use Arcanum\Quill\CorrelationProcessor; use Monolog\Handler\ErrorLogHandler; use Monolog\Handler\HandlerInterface; use Psr\Log\LoggerInterface; @@ -93,8 +94,18 @@ public function bootstrap(Application $container): void */ $filesDirectory = $kernel->filesDirectory(); - $container->factory(QuillLogger::class, fn() => $this->makeQuillLogger((array)$logConfig, $filesDirectory)); + $processor = new CorrelationProcessor(); + $container->instance(CorrelationProcessor::class, $processor); + + $container->factory( + QuillLogger::class, + fn() => $this->makeQuillLogger((array)$logConfig, $filesDirectory, $processor), + ); $container->service(\Arcanum\Quill\ChannelLogger::class, QuillLogger::class); + + if (!$container->has(LoggerInterface::class)) { + $container->service(LoggerInterface::class, QuillLogger::class); + } } /** @@ -150,12 +161,17 @@ private function makeHandler(string $handlerName, array $handlerConfig, string $ * @param string[] $handlerNames * @param array $handlers */ - private function makeChannel(string $name, array $handlerNames, array $handlers): Channel - { + private function makeChannel( + string $name, + array $handlerNames, + array $handlers, + CorrelationProcessor $processor, + ): Channel { $monologger = new \Monolog\Logger($name); foreach ($handlerNames as $handlerName) { $monologger->pushHandler($handlers[$handlerName]); } + $monologger->pushProcessor($processor); return new Channel($monologger); } @@ -167,8 +183,11 @@ private function makeChannel(string $name, array $handlerNames, array $handlers) * channels: array * } $logConfig */ - private function makeQuillLogger(array $logConfig, string $filesDirectory): LoggerInterface - { + private function makeQuillLogger( + array $logConfig, + string $filesDirectory, + CorrelationProcessor $processor, + ): LoggerInterface { $handlers = []; // Build the configured handlers @@ -179,7 +198,7 @@ private function makeQuillLogger(array $logConfig, string $filesDirectory): Logg // Build the configured channels $channels = []; foreach ($logConfig['channels'] as $channelName => $channelHandlers) { - $channels[] = $this->makeChannel($channelName, $channelHandlers, $handlers); + $channels[] = $this->makeChannel($channelName, $channelHandlers, $handlers, $processor); } return new QuillLogger(...$channels); diff --git a/src/Ignition/Bootstrap/Routing.php b/src/Ignition/Bootstrap/Routing.php index c2c5cfc..7cf96f8 100644 --- a/src/Ignition/Bootstrap/Routing.php +++ b/src/Ignition/Bootstrap/Routing.php @@ -107,7 +107,9 @@ private function registerRouter(Application $container, Configuration $config): if (!is_dir($absolutePagesDir) && $container->has(\Psr\Log\LoggerInterface::class)) { /** @var \Psr\Log\LoggerInterface $logger */ $logger = $container->get(\Psr\Log\LoggerInterface::class); - $logger->debug("Pages directory does not exist: {$absolutePagesDir}. No pages will be discovered."); + $logger->debug('Pages directory does not exist', [ + 'path' => $absolutePagesDir, + ]); } // Page cache configuration. @@ -145,8 +147,13 @@ private function registerRouter(Application $container, Configuration $config): $pages = new PageResolver(namespace: $pagesNamespace); $container->instance(PageResolver::class, $pages); - $container->factory(Router::class, function () use ($resolver, $routeMap, $pages, $defaultFormat) { - return new HttpRouter($resolver, $routeMap, $pages, $defaultFormat); + $container->factory(Router::class, function () use ($container, $resolver, $routeMap, $pages, $defaultFormat) { + $logger = $container->has(\Psr\Log\LoggerInterface::class) + ? $container->get(\Psr\Log\LoggerInterface::class) + : null; + + /** @var ?\Psr\Log\LoggerInterface $logger */ + return new HttpRouter($resolver, $routeMap, $pages, $defaultFormat, $logger); }); $container->instance(UrlResolver::class, new UrlResolver( diff --git a/src/Ignition/HyperKernel.php b/src/Ignition/HyperKernel.php index 48d8884..2bd1a53 100644 --- a/src/Ignition/HyperKernel.php +++ b/src/Ignition/HyperKernel.php @@ -15,10 +15,13 @@ use Arcanum\Hourglass\Stopwatch; use Arcanum\Hyper\HttpMiddleware; use Arcanum\Hyper\StatusCode; +use Arcanum\Quill\CorrelationProcessor; +use Arcanum\Toolkit\Random; use Psr\Http\Message\ServerRequestInterface; use Psr\Http\Message\ResponseInterface; use Psr\Http\Server\MiddlewareInterface; use Psr\Http\Server\RequestHandlerInterface; +use Psr\Log\LoggerInterface; /** * A HyperKernel is the initial entry point for an HTTP application. @@ -201,6 +204,13 @@ public function middleware(string $middlewareClass): void */ public function handle(ServerRequestInterface $request): ResponseInterface { + $logger = $this->resolveLogger(); + $this->beginCorrelation(); + + $method = $request->getMethod(); + $path = $request->getUri()->getPath(); + $logger?->debug('Request received', ['method' => $method, 'path' => $path]); + try { $request = $this->prepareRequest($request); @@ -216,6 +226,8 @@ public function handle(ServerRequestInterface $request): ResponseInterface new CallableHandler(fn() => $this->handleException($e)), ); $this->lastResponse = $response; + $this->logRequestHandled($logger, $method, $path, $response); + $this->endCorrelation(); return $response; } @@ -250,6 +262,8 @@ public function handle(ServerRequestInterface $request): ResponseInterface } $this->lastResponse = $response; + $this->logRequestHandled($logger, $method, $path, $response); + $this->endCorrelation(); return $response; } @@ -445,4 +459,45 @@ public function terminate(): void Stopwatch::tap('arcanum.complete'); } + + private function resolveLogger(): ?LoggerInterface + { + if ($this->container->has(LoggerInterface::class)) { + /** @var LoggerInterface */ + return $this->container->get(LoggerInterface::class); + } + + return null; + } + + private function beginCorrelation(): void + { + if ($this->container->has(CorrelationProcessor::class)) { + /** @var CorrelationProcessor $processor */ + $processor = $this->container->get(CorrelationProcessor::class); + $processor->setCorrelationId(Random::hex(8)); + } + } + + private function endCorrelation(): void + { + if ($this->container->has(CorrelationProcessor::class)) { + /** @var CorrelationProcessor $processor */ + $processor = $this->container->get(CorrelationProcessor::class); + $processor->clearCorrelationId(); + } + } + + private function logRequestHandled( + ?LoggerInterface $logger, + string $method, + string $path, + ResponseInterface $response, + ): void { + $logger?->info('Request handled', [ + 'method' => $method, + 'path' => $path, + 'status' => $response->getStatusCode(), + ]); + } } diff --git a/src/Ignition/RouteDispatcher.php b/src/Ignition/RouteDispatcher.php index cae2b79..af4c320 100644 --- a/src/Ignition/RouteDispatcher.php +++ b/src/Ignition/RouteDispatcher.php @@ -13,6 +13,7 @@ use Arcanum\Hyper\HttpMiddleware; use Psr\Container\ContainerInterface; use Psr\Http\Server\RequestHandlerInterface; +use Psr\Log\LoggerInterface; /** * Composes per-route middleware with the existing command bus. @@ -31,6 +32,7 @@ public function __construct( private readonly ContainerInterface $container, private readonly MiddlewareRegistry $middlewareRegistry, private readonly Bus $bus, + private readonly ?LoggerInterface $logger = null, ) { } @@ -53,6 +55,13 @@ public function dispatch(object $dto, Route $route): object $this->resolvedDtoClass = $route->dtoClass; $mw = $this->middlewareRegistry->for($route->dtoClass); + $this->logger?->debug('Dispatching', [ + 'dto' => $route->dtoClass, + 'handler_prefix' => $route->handlerPrefix, + 'before_middleware' => count($mw->before), + 'after_middleware' => count($mw->after), + ]); + if ($mw->before === [] && $mw->after === []) { return $this->bus->dispatch($dto, prefix: $route->handlerPrefix); } diff --git a/src/Ignition/RuneKernel.php b/src/Ignition/RuneKernel.php index 7b9d0ff..0400cc7 100644 --- a/src/Ignition/RuneKernel.php +++ b/src/Ignition/RuneKernel.php @@ -16,6 +16,7 @@ use Arcanum\Flow\Conveyor\Query; use Arcanum\Flow\Conveyor\QueryResult; use Arcanum\Hourglass\Stopwatch; +use Arcanum\Quill\CorrelationProcessor; use Arcanum\Rune\CliExceptionWriter; use Arcanum\Rune\BuiltInRegistry; use Arcanum\Rune\Event\CommandCompleted; @@ -27,6 +28,8 @@ use Arcanum\Rune\Input; use Arcanum\Rune\Output; use Arcanum\Shodo\CliFormatRegistry; +use Arcanum\Toolkit\Random; +use Psr\Log\LoggerInterface; /** * The CLI entry point — parallel to HyperKernel for HTTP. @@ -159,6 +162,9 @@ public function bootstrap(Application $container): void */ public function handle(array $argv): int { + $logger = $this->resolveLogger(); + $this->beginCorrelation(); + $input = Input::fromArgv($argv); /** @var Output $output */ @@ -166,9 +172,13 @@ public function handle(array $argv): int if ($input->command() === '') { $this->splash($output); + $this->endCorrelation(); return ExitCode::Success->value; } + $commandName = $input->command(); + $logger?->debug('Command received', ['command' => $commandName]); + Stopwatch::tap('command.received'); $this->lifecycle->dispatch(new CommandReceived($input)); @@ -182,8 +192,14 @@ public function handle(array $argv): int $exitCode = $this->handleException($e, $output); } + $logger?->info('Command completed', [ + 'command' => $commandName, + 'exit_code' => $exitCode, + ]); + $this->lastInput = $input; $this->lastExitCode = $exitCode; + $this->endCorrelation(); return $exitCode; } @@ -312,6 +328,34 @@ public function terminate(): void Stopwatch::tap('arcanum.complete'); } + private function resolveLogger(): ?LoggerInterface + { + if ($this->container->has(LoggerInterface::class)) { + /** @var LoggerInterface */ + return $this->container->get(LoggerInterface::class); + } + + return null; + } + + private function beginCorrelation(): void + { + if ($this->container->has(CorrelationProcessor::class)) { + /** @var CorrelationProcessor $processor */ + $processor = $this->container->get(CorrelationProcessor::class); + $processor->setCorrelationId(Random::hex(8)); + } + } + + private function endCorrelation(): void + { + if ($this->container->has(CorrelationProcessor::class)) { + /** @var CorrelationProcessor $processor */ + $processor = $this->container->get(CorrelationProcessor::class); + $processor->clearCorrelationId(); + } + } + private function splash(Output $output): void { $name = 'Arcanum'; diff --git a/src/Quill/CorrelationProcessor.php b/src/Quill/CorrelationProcessor.php new file mode 100644 index 0000000..6226ec1 --- /dev/null +++ b/src/Quill/CorrelationProcessor.php @@ -0,0 +1,41 @@ +correlationId = $correlationId; + } + + public function clearCorrelationId(): void + { + $this->correlationId = null; + } + + public function __invoke(LogRecord $record): LogRecord + { + if ($this->correlationId === null) { + return $record; + } + + return $record->with(extra: array_merge($record->extra, [ + 'correlation_id' => $this->correlationId, + ])); + } +} diff --git a/src/Quill/README.md b/src/Quill/README.md index c5c09cb..27df6df 100644 --- a/src/Quill/README.md +++ b/src/Quill/README.md @@ -95,6 +95,26 @@ return [ Standard PSR-3 calls (`$logger->info(...)`) always route to the `default` channel. Use `$logger->channel('name')` to target a specific channel. +## Correlation processor + +`CorrelationProcessor` is a Monolog processor that tags every log record with a `correlation_id` for grouping related log lines within a unit of work (HTTP request, CLI command, queued job). + +```php +use Arcanum\Quill\CorrelationProcessor; + +$processor = new CorrelationProcessor(); +$processor->setCorrelationId('abc123'); + +// Every log record now includes correlation_id in its extra data +$logger->info('Something happened'); +// → extra: { correlation_id: "abc123" } + +$processor->clearCorrelationId(); +// → no correlation_id added after clearing +``` + +In the framework, `Bootstrap\Logger` registers a single `CorrelationProcessor` and pushes it onto every Monolog channel. The kernels (`HyperKernel`, `RuneKernel`) set and clear the ID at the start and end of each `handle()` cycle, so all log lines from a single request or command share the same correlation ID. Note: correlation IDs require Quill/Monolog — apps that bind a custom `LoggerInterface` before `Bootstrap\Logger` runs will need to handle correlation in their own logger implementation. + ## At a glance ``` diff --git a/src/Session/SessionMiddleware.php b/src/Session/SessionMiddleware.php index b467e9e..98c748a 100644 --- a/src/Session/SessionMiddleware.php +++ b/src/Session/SessionMiddleware.php @@ -8,6 +8,7 @@ use Psr\Http\Message\ServerRequestInterface; use Psr\Http\Server\MiddlewareInterface; use Psr\Http\Server\RequestHandlerInterface; +use Psr\Log\LoggerInterface; /** * PSR-15 middleware that manages the session lifecycle. @@ -27,6 +28,7 @@ public function __construct( private readonly SessionDriver $driver, private readonly SessionConfig $config, private readonly ActiveSession $registry, + private readonly ?LoggerInterface $logger = null, ) { } @@ -39,6 +41,9 @@ public function process(ServerRequestInterface $request, RequestHandlerInterface $originalId = is_string($cookieValue) ? SessionId::fromString($cookieValue) : null; $id = $originalId ?? SessionId::generate(); + $isNew = $originalId === null; + $this->logger?->debug($isNew ? 'Session started' : 'Session loaded'); + // Load session data from driver. $rawCookie = is_string($cookieValue) ? $cookieValue : ''; $data = $originalId !== null ? $this->loadData($id, $rawCookie) : []; @@ -76,13 +81,16 @@ private function finalizeSession( // If the session was invalidated, destroy the old session data. if ($session->wasInvalidated() && $originalId !== null) { $this->driver->destroy($originalId->value); + $this->logger?->notice('Session invalidated'); } elseif ($session->wasRegenerated() && $originalId !== null) { // Regenerated — destroy old ID, keep data under new ID. $this->driver->destroy($originalId->value); + $this->logger?->notice('Session regenerated'); } // Persist session data under the (possibly new) ID. $this->driver->write($session->id()->value, $session->toArray(), max(1, $this->config->lifetime)); + $this->logger?->debug('Session saved'); // Set the session cookie. $cookieHeader = $this->buildCookieHeader($session); diff --git a/src/Throttle/RateLimiter.php b/src/Throttle/RateLimiter.php index aa52b80..2fa5941 100644 --- a/src/Throttle/RateLimiter.php +++ b/src/Throttle/RateLimiter.php @@ -4,6 +4,7 @@ namespace Arcanum\Throttle; +use Psr\Log\LoggerInterface; use Psr\SimpleCache\CacheInterface; /** @@ -18,6 +19,7 @@ final class RateLimiter public function __construct( private readonly CacheInterface $cache, private readonly Throttler $throttler = new TokenBucket(), + private readonly ?LoggerInterface $logger = null, ) { } @@ -29,6 +31,21 @@ public function __construct( */ public function attempt(string $key, int $limit, int $windowSeconds): Quota { - return $this->throttler->attempt($this->cache, $key, $limit, $windowSeconds); + $quota = $this->throttler->attempt($this->cache, $key, $limit, $windowSeconds); + + if (!$quota->isAllowed()) { + $this->logger?->notice('Rate limit exceeded', [ + 'key' => $key, + 'limit' => $limit, + 'retry_after' => $quota->retryAfter, + ]); + } else { + $this->logger?->debug('Rate check passed', [ + 'key' => $key, + 'remaining' => $quota->remaining, + ]); + } + + return $quota; } } diff --git a/tests/Atlas/CliRouterTest.php b/tests/Atlas/CliRouterTest.php index 058d0c8..85a6b8f 100644 --- a/tests/Atlas/CliRouterTest.php +++ b/tests/Atlas/CliRouterTest.php @@ -14,6 +14,7 @@ use PHPUnit\Framework\TestCase; use PHPUnit\Framework\Attributes\CoversClass; use PHPUnit\Framework\Attributes\UsesClass; +use Psr\Log\LoggerInterface; #[CoversClass(CliRouter::class)] #[UsesClass(CliRouteMap::class)] @@ -481,4 +482,68 @@ public function testHelpFlagWorksWithCommands(): void $this->assertTrue($route->isHelp); $this->assertSame('Arcanum\\Test\\Fixture\\Contact\\Command\\Submit', $route->dtoClass); } + + // --------------------------------------------------------------- + // Logging + // --------------------------------------------------------------- + + public function testLogsConventionRouteResolved(): void + { + // Arrange + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('debug') + ->with('Command resolved', [ + 'type' => 'convention', + 'dto' => 'Arcanum\\Test\\Fixture\\Shop\\Query\\Products', + ]); + + $router = new CliRouter( + new ConventionResolver(rootNamespace: 'Arcanum\\Test\\Fixture'), + logger: $logger, + ); + + $input = new Input('query:shop:products'); + + // Act + $router->resolve($input); + } + + public function testLogsCommandNotFound(): void + { + // Arrange + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('debug') + ->with('Command not found', [ + 'input' => 'query:nonexistent:thing', + ]); + + $router = new CliRouter( + new ConventionResolver(rootNamespace: 'Arcanum\\Test\\Fixture'), + logger: $logger, + ); + + $input = new Input('query:nonexistent:thing'); + + // Act & Assert + $this->expectException(UnresolvableRoute::class); + $router->resolve($input); + } + + public function testWorksWithNullLogger(): void + { + // Arrange — no logger passed (null by default) + $router = new CliRouter( + new ConventionResolver(rootNamespace: 'Arcanum\\Test\\Fixture'), + ); + + $input = new Input('query:shop:products'); + + // Act + $route = $router->resolve($input); + + // Assert — resolves normally without a logger + $this->assertSame('Arcanum\\Test\\Fixture\\Shop\\Query\\Products', $route->dtoClass); + } } diff --git a/tests/Atlas/HttpRouterTest.php b/tests/Atlas/HttpRouterTest.php index 27af881..b3d20be 100644 --- a/tests/Atlas/HttpRouterTest.php +++ b/tests/Atlas/HttpRouterTest.php @@ -20,6 +20,7 @@ use PHPUnit\Framework\Attributes\UsesClass; use Psr\Http\Message\ServerRequestInterface; use Psr\Http\Message\UriInterface; +use Psr\Log\LoggerInterface; #[CoversClass(HttpRouter::class)] #[UsesClass(AllowedFormats::class)] @@ -894,4 +895,111 @@ public function testDefaultFormatRejectedWhenNotAllowed(): void $this->expectException(HttpException::class); $router->resolve($request); } + + // ----------------------------------------------------------- + // Logging + // ----------------------------------------------------------- + + public function testLogsConventionRouteResolution(): void + { + // Arrange + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('debug') + ->with('Route resolved', $this->callback( + fn(array $ctx) => $ctx['type'] === 'convention' + && str_contains($ctx['dto'], 'Products'), + )); + + $router = new HttpRouter( + new ConventionResolver(self::ROOT_NS), + logger: $logger, + ); + + // Act + $router->resolve($this->stubRequest('GET', '/shop/products')); + } + + public function testLogsRouteNotFound(): void + { + // Arrange + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('debug') + ->with('Route not found', $this->callback( + fn(array $ctx) => $ctx['path'] === '/nonexistent', + )); + + $router = new HttpRouter( + new ConventionResolver(self::ROOT_NS), + logger: $logger, + ); + + // Act & Assert + try { + $router->resolve($this->stubRequest('GET', '/nonexistent')); + } catch (HttpException) { + // Expected + } + } + + public function testLogsMethodNotAllowed(): void + { + // Arrange — Reports\Query\Summary exists, no Command\Summary + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('notice') + ->with('Method not allowed', $this->callback( + fn(array $ctx) => $ctx['method'] === 'PUT' + && $ctx['path'] === '/reports/summary', + )); + + $router = new HttpRouter( + new ConventionResolver(self::ROOT_NS), + logger: $logger, + ); + + // Act & Assert + try { + $router->resolve($this->stubRequest('PUT', '/reports/summary')); + } catch (MethodNotAllowed) { + // Expected + } + } + + public function testLogsFormatNotAcceptable(): void + { + // Arrange — Shop\Query\Inventory has #[AllowedFormats('json')] + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('notice') + ->with('Format not acceptable', $this->callback( + fn(array $ctx) => $ctx['format'] === 'csv' + && $ctx['allowed'] === ['json'], + )); + + $router = new HttpRouter( + new ConventionResolver(self::ROOT_NS), + logger: $logger, + ); + + // Act & Assert + try { + $router->resolve($this->stubRequest('GET', '/shop/inventory.csv')); + } catch (HttpException) { + // Expected + } + } + + public function testWorksWithNullLogger(): void + { + // Arrange — no logger, should resolve without error + $router = new HttpRouter(new ConventionResolver(self::ROOT_NS)); + + // Act + $route = $router->resolve($this->stubRequest('GET', '/shop/products')); + + // Assert + $this->assertSame('json', $route->format); + } } diff --git a/tests/Auth/AuthMiddlewareTest.php b/tests/Auth/AuthMiddlewareTest.php index 134cdf4..7d0112b 100644 --- a/tests/Auth/AuthMiddlewareTest.php +++ b/tests/Auth/AuthMiddlewareTest.php @@ -18,6 +18,7 @@ use Psr\Http\Message\ResponseInterface; use Psr\Http\Message\ServerRequestInterface; use Psr\Http\Server\RequestHandlerInterface; +use Psr\Log\LoggerInterface; #[CoversClass(AuthMiddleware::class)] #[UsesClass(ActiveIdentity::class)] @@ -267,4 +268,53 @@ function (ServerRequestInterface $r) use (&$capturedRequest) { $this->assertNotNull($capturedRequest); $this->assertNull($capturedRequest->getAttribute('auth.token_authenticated')); } + + // ----------------------------------------------------------- + // Logger instrumentation + // ----------------------------------------------------------- + + public function testLogsIdentityResolved(): void + { + // Arrange + $identity = new SimpleIdentity('user-1'); + $guard = $this->createStub(Guard::class); + $guard->method('resolve')->willReturn($identity); + + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('info') + ->with('Identity resolved', $this->callback(function (array $context): bool { + return isset($context['guard']) && is_string($context['guard']); + })); + + $active = new ActiveIdentity(); + $middleware = new AuthMiddleware($guard, $active, $logger); + + $handler = $this->createStub(RequestHandlerInterface::class); + $handler->method('handle')->willReturn($this->createStub(ResponseInterface::class)); + + // Act + $middleware->process($this->createStub(ServerRequestInterface::class), $handler); + } + + public function testLogsNoIdentityResolved(): void + { + // Arrange + $guard = $this->createStub(Guard::class); + $guard->method('resolve')->willReturn(null); + + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('debug') + ->with('No identity resolved'); + + $active = new ActiveIdentity(); + $middleware = new AuthMiddleware($guard, $active, $logger); + + $handler = $this->createStub(RequestHandlerInterface::class); + $handler->method('handle')->willReturn($this->createStub(ResponseInterface::class)); + + // Act + $middleware->process($this->createStub(ServerRequestInterface::class), $handler); + } } diff --git a/tests/Flow/Conveyor/MiddlewareBusTest.php b/tests/Flow/Conveyor/MiddlewareBusTest.php index 7a60d9e..215c45d 100644 --- a/tests/Flow/Conveyor/MiddlewareBusTest.php +++ b/tests/Flow/Conveyor/MiddlewareBusTest.php @@ -176,7 +176,10 @@ public function testFallbackLogsWarningInDebugMode(): void $loggerMock->expects($this->once()) ->method('warning') - ->with($this->stringContains('DeleteDoSomethingHandler')); + ->with( + 'Handler not found, falling back to unprefixed', + $this->callback(fn(array $ctx) => str_contains($ctx['prefixed'], 'DeleteDoSomethingHandler')), + ); $bus = new MiddlewareBus(new Container(), debug: true, logger: $loggerMock); @@ -184,7 +187,7 @@ public function testFallbackLogsWarningInDebugMode(): void $bus->dispatch(new DoSomething('test'), prefix: 'Delete'); } - public function testFallbackDoesNotLogInProductionMode(): void + public function testFallbackLogsWarningInProductionMode(): void { // Arrange $channel = new \Arcanum\Quill\Channel(new \Monolog\Logger('test')); @@ -195,8 +198,12 @@ public function testFallbackDoesNotLogInProductionMode(): void ->onlyMethods(['warning']) ->getMock(); - $loggerMock->expects($this->never()) - ->method('warning'); + $loggerMock->expects($this->once()) + ->method('warning') + ->with( + 'Handler not found, falling back to unprefixed', + $this->anything(), + ); $bus = new MiddlewareBus(new Container(), debug: false, logger: $loggerMock); @@ -337,7 +344,8 @@ public function testLogsWarningInProductionWhenValidationAttributesPresentButNoG // Arrange $logger = $this->createMock(LoggerInterface::class); $logger->expects($this->once())->method('warning')->with( - $this->stringContains('has validation rules but no ValidationGuard'), + 'ValidationGuard missing for DTO with rules', + $this->callback(fn(array $ctx) => isset($ctx['dto'])), ); $bus = new MiddlewareBus(new Container(), debug: false, logger: $logger); diff --git a/tests/Forge/Migration/MigratorTest.php b/tests/Forge/Migration/MigratorTest.php index 3e31c98..823c8e6 100644 --- a/tests/Forge/Migration/MigratorTest.php +++ b/tests/Forge/Migration/MigratorTest.php @@ -16,6 +16,7 @@ use Arcanum\Forge\PdoConnection; use Arcanum\Forge\WriteResult; use Arcanum\Flow\Sequence\Cursor; +use Psr\Log\LoggerInterface; use PHPUnit\Framework\TestCase; use PHPUnit\Framework\Attributes\CoversClass; use PHPUnit\Framework\Attributes\UsesClass; @@ -408,4 +409,96 @@ public function testMigrateAndRollbackRoundTrip(): void /** @var array{c: int|string} $countRow */ $this->assertSame(0, (int) $countRow['c']); } + + // ------------------------------------------------------------------ + // Logging + // ------------------------------------------------------------------ + + public function testMigrateLogsMigrationApplied(): void + { + // Arrange + $this->writeMigration( + '20260410120000_create_items.sql', + 'CREATE TABLE items (id INTEGER PRIMARY KEY)', + ); + + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('info') + ->with('Migration applied', $this->callback( + fn(array $ctx) => $ctx['file'] === '20260410120000_create_items.sql' + && isset($ctx['elapsed_ms']), + )); + + $repo = new MigrationRepository($this->connection, 'sqlite'); + $migrator = new Migrator($this->connection, $repo, $this->migrationsDir, $logger); + + // Act + $migrator->migrate(); + } + + public function testRollbackLogsMigrationRolledBack(): void + { + // Arrange + $this->writeMigration( + '20260410120000_create_items.sql', + 'CREATE TABLE items (id INTEGER PRIMARY KEY)', + 'DROP TABLE items', + ); + + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('info') + ->with($this->logicalOr('Migration applied', 'Migration rolled back'), $this->anything()); + + $repo = new MigrationRepository($this->connection, 'sqlite'); + $migrator = new Migrator($this->connection, $repo, $this->migrationsDir, $logger); + $migrator->migrate(); + + // Reset expectations for the rollback + $logger2 = $this->createMock(LoggerInterface::class); + $logger2->expects($this->once()) + ->method('info') + ->with('Migration rolled back', $this->callback( + fn(array $ctx) => $ctx['file'] === '20260410120000_create_items.sql' + && isset($ctx['elapsed_ms']), + )); + + $migrator2 = new Migrator($this->connection, $repo, $this->migrationsDir, $logger2); + + // Act + $migrator2->rollback(); + } + + public function testMigrateLogsChecksumWarning(): void + { + // Arrange — apply a migration, then modify the file + $this->writeMigration( + '20260410120000_create_items.sql', + 'CREATE TABLE items (id INTEGER PRIMARY KEY)', + ); + + $repo = new MigrationRepository($this->connection, 'sqlite'); + $migrator = new Migrator($this->connection, $repo, $this->migrationsDir); + $migrator->migrate(); + + // Modify the file after applying + $this->writeMigration( + '20260410120000_create_items.sql', + 'CREATE TABLE items (id INTEGER PRIMARY KEY, name TEXT)', + ); + + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('warning') + ->with('Checksum mismatch', $this->callback( + fn(array $ctx) => $ctx['file'] === '20260410120000_create_items.sql' + && isset($ctx['expected'], $ctx['actual']), + )); + + $migrator2 = new Migrator($this->connection, $repo, $this->migrationsDir, $logger); + + // Act + $migrator2->migrate(); + } } diff --git a/tests/Ignition/Bootstrap/LoggerTest.php b/tests/Ignition/Bootstrap/LoggerTest.php index 7ee3b74..0f4d882 100644 --- a/tests/Ignition/Bootstrap/LoggerTest.php +++ b/tests/Ignition/Bootstrap/LoggerTest.php @@ -12,6 +12,7 @@ use Arcanum\Quill\Channel; use Arcanum\Quill\Handler; use Arcanum\Quill\Logger as QuillLogger; +use Arcanum\Quill\CorrelationProcessor; use PHPUnit\Framework\TestCase; use PHPUnit\Framework\Attributes\CoversClass; use PHPUnit\Framework\Attributes\UsesClass; @@ -27,6 +28,7 @@ #[UsesClass(\Arcanum\Gather\Registry::class)] #[UsesClass(QuillLogger::class)] #[UsesClass(Channel::class)] +#[UsesClass(CorrelationProcessor::class)] final class LoggerTest extends TestCase { private string $filesDir; @@ -264,6 +266,72 @@ public function testChannelWithMultipleHandlers(): void $this->assertTrue(file_exists($this->filesDir . '/logs/app.log')); } + public function testBindsLoggerInterfaceToQuillLogger(): void + { + // Arrange + $container = $this->buildContainer($this->defaultLogConfig()); + $bootstrapper = new Logger(); + + // Act + $bootstrapper->bootstrap($container); + + // Assert + $this->assertTrue($container->has(LoggerInterface::class)); + $this->assertInstanceOf(LoggerInterface::class, $container->get(LoggerInterface::class)); + } + + public function testRespectsExistingLoggerInterfaceBinding(): void + { + // Arrange + $container = $this->buildContainer($this->defaultLogConfig()); + $customLogger = $this->createStub(LoggerInterface::class); + $container->instance(LoggerInterface::class, $customLogger); + $bootstrapper = new Logger(); + + // Act + $bootstrapper->bootstrap($container); + + // Assert — should still be the custom logger, not QuillLogger + $this->assertSame($customLogger, $container->get(LoggerInterface::class)); + } + + public function testRegistersCorrelationProcessor(): void + { + // Arrange + $container = $this->buildContainer($this->defaultLogConfig()); + $bootstrapper = new Logger(); + + // Act + $bootstrapper->bootstrap($container); + + // Assert + $this->assertTrue($container->has(CorrelationProcessor::class)); + $this->assertInstanceOf(CorrelationProcessor::class, $container->get(CorrelationProcessor::class)); + } + + public function testCorrelationIdAppearsInLogOutput(): void + { + // Arrange + $container = $this->buildContainer($this->defaultLogConfig()); + $bootstrapper = new Logger(); + $bootstrapper->bootstrap($container); + + /** @var CorrelationProcessor $processor */ + $processor = $container->get(CorrelationProcessor::class); + $processor->setCorrelationId('test-corr-123'); + + /** @var QuillLogger $logger */ + $logger = $container->get(QuillLogger::class); + + // Act + $logger->info('correlation test'); + + // Assert — the log file should contain the correlation ID + $logContent = file_get_contents($this->filesDir . '/logs/default.log'); + $this->assertIsString($logContent); + $this->assertStringContainsString('test-corr-123', $logContent); + } + public function testSyslogHandler(): void { // Arrange diff --git a/tests/Ignition/HyperKernelTest.php b/tests/Ignition/HyperKernelTest.php index 9beaa1b..42a515b 100644 --- a/tests/Ignition/HyperKernelTest.php +++ b/tests/Ignition/HyperKernelTest.php @@ -29,6 +29,7 @@ use Psr\Http\Message\StreamInterface; use Psr\Http\Server\MiddlewareInterface; use Psr\Http\Server\RequestHandlerInterface; +use Psr\Log\LoggerInterface; #[CoversClass(HyperKernel::class)] #[UsesClass(CallableHandler::class)] @@ -43,6 +44,9 @@ #[UsesClass(RouteDispatcher::class)] #[UsesClass(MiddlewareRegistry::class)] #[UsesClass(Route::class)] +#[UsesClass(\Arcanum\Toolkit\Random::class)] +#[UsesClass(\Arcanum\Toolkit\Hex::class)] +#[UsesClass(\Arcanum\Quill\CorrelationProcessor::class)] final class HyperKernelTest extends TestCase { // ----------------------------------------------------------- @@ -166,6 +170,8 @@ public function testHandleRendersExceptionViaExceptionRenderer(): void [ExceptionHandler::class, false], [ExceptionRenderer::class, true], [EventDispatcherInterface::class, false], + [LoggerInterface::class, false], + [\Arcanum\Quill\CorrelationProcessor::class, false], ]); $container->method('get')->willReturnCallback( fn(string $id) => $id === ExceptionRenderer::class ? $renderer : $bootstrapper @@ -200,6 +206,8 @@ public function testHandleReportsExceptionBeforeRendering(): void [ExceptionHandler::class, true], [ExceptionRenderer::class, true], [EventDispatcherInterface::class, false], + [LoggerInterface::class, false], + [\Arcanum\Quill\CorrelationProcessor::class, false], ]); $container->method('get')->willReturnCallback( fn(string $id) => match ($id) { @@ -632,6 +640,8 @@ public function process( [ExceptionHandler::class, false], [ExceptionRenderer::class, true], [EventDispatcherInterface::class, false], + [LoggerInterface::class, false], + [\Arcanum\Quill\CorrelationProcessor::class, false], ]); $class = get_class($middleware); @@ -687,6 +697,8 @@ public function process( [ExceptionHandler::class, false], [ExceptionRenderer::class, true], [EventDispatcherInterface::class, false], + [LoggerInterface::class, false], + [\Arcanum\Quill\CorrelationProcessor::class, false], ]); $class = get_class($middleware); @@ -753,6 +765,8 @@ public function testExceptionRendererHonoursDefaultFormatWhenNoExtension(): void [\Arcanum\Gather\Configuration::class, true], [EventDispatcherInterface::class, false], [RouteDispatcher::class, false], + [LoggerInterface::class, false], + [\Arcanum\Quill\CorrelationProcessor::class, false], ]); $container->method('get')->willReturnCallback( fn(string $id) => match ($id) { @@ -833,6 +847,8 @@ public function testHandleExceptionSetsDtoClassFromRouteDispatcher(): void [\Arcanum\Gather\Configuration::class, true], [EventDispatcherInterface::class, false], [RouteDispatcher::class, true], + [LoggerInterface::class, false], + [\Arcanum\Quill\CorrelationProcessor::class, false], ]); $container->method('get')->willReturnCallback( fn(string $id) => match ($id) { @@ -896,6 +912,8 @@ public function testHandleExceptionFallsBackToSetResolvedDtoClass(): void [\Arcanum\Gather\Configuration::class, true], [EventDispatcherInterface::class, false], [RouteDispatcher::class, false], + [LoggerInterface::class, false], + [\Arcanum\Quill\CorrelationProcessor::class, false], ]); $container->method('get')->willReturnCallback( fn(string $id) => match ($id) { @@ -970,6 +988,8 @@ public function process( [ExceptionHandler::class, true], [ExceptionRenderer::class, true], [EventDispatcherInterface::class, false], + [LoggerInterface::class, false], + [\Arcanum\Quill\CorrelationProcessor::class, false], ]); $class = get_class($middleware); @@ -992,4 +1012,148 @@ public function process( // Assert — the rendered error response was returned, not bubbled $this->assertSame($errorResponse, $response); } + + // ----------------------------------------------------------- + // Lifecycle logging + // ----------------------------------------------------------- + + public function testHandleLogsRequestReceivedAndHandled(): void + { + // Arrange + $kernel = new CapturingKernel('/app'); + + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('debug') + ->with('Request received', $this->callback( + fn(array $ctx) => $ctx['method'] === 'GET' && $ctx['path'] === '/test', + )); + $logger->expects($this->once()) + ->method('info') + ->with('Request handled', $this->callback( + fn(array $ctx) => $ctx['method'] === 'GET' + && $ctx['path'] === '/test' + && $ctx['status'] === 200, + )); + + $bootstrapper = $this->createStub(Bootstrapper::class); + + $container = $this->createStub(Application::class); + $container->method('has')->willReturnCallback( + fn(string $id) => $id === LoggerInterface::class, + ); + $container->method('get')->willReturnCallback( + fn(string $id) => $id === LoggerInterface::class ? $logger : $bootstrapper, + ); + $kernel->bootstrap($container); + + $uri = $this->createStub(\Psr\Http\Message\UriInterface::class); + $uri->method('getPath')->willReturn('/test'); + + $request = $this->createStub(ServerRequestInterface::class); + $request->method('getMethod')->willReturn('GET'); + $request->method('getUri')->willReturn($uri); + + // Act + $kernel->handle($request); + } + + public function testHandleLogsOnExceptionPath(): void + { + // Arrange — default handleRequest throws, so the error path is taken. + // The INFO log should still fire with the error response status. + $kernel = new HyperKernel('/app'); + + $errorResponse = $this->createStub(ResponseInterface::class); + $errorResponse->method('getStatusCode')->willReturn(404); + + $renderer = $this->createStub(ExceptionRenderer::class); + $renderer->method('render')->willReturn($errorResponse); + + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once())->method('debug'); + $logger->expects($this->once()) + ->method('info') + ->with('Request handled', $this->callback( + fn(array $ctx) => $ctx['status'] === 404, + )); + + $bootstrapper = $this->createStub(Bootstrapper::class); + + $container = $this->createStub(Application::class); + $container->method('has')->willReturnCallback( + fn(string $id) => match ($id) { + LoggerInterface::class, ExceptionRenderer::class => true, + default => false, + }, + ); + $container->method('get')->willReturnCallback( + fn(string $id) => match ($id) { + LoggerInterface::class => $logger, + ExceptionRenderer::class => $renderer, + default => $bootstrapper, + }, + ); + $kernel->bootstrap($container); + + $uri = $this->createStub(\Psr\Http\Message\UriInterface::class); + $uri->method('getPath')->willReturn('/not-found'); + + $request = $this->createStub(ServerRequestInterface::class); + $request->method('getMethod')->willReturn('GET'); + $request->method('getUri')->willReturn($uri); + + // Act + $kernel->handle($request); + } + + public function testHandleWorksWithoutLogger(): void + { + // Arrange — no logger in container, handle should still work + $kernel = new CapturingKernel('/app'); + + $bootstrapper = $this->createStub(Bootstrapper::class); + $container = $this->createStub(Application::class); + $container->method('has')->willReturn(false); + $container->method('get')->willReturn($bootstrapper); + $kernel->bootstrap($container); + + // Act + $kernel->handle($this->createStub(ServerRequestInterface::class)); + + // Assert — request was handled normally + $this->assertNotNull($kernel->capturedRequest); + } + + public function testHandleSetsAndClearsCorrelationId(): void + { + // Arrange + $kernel = new CapturingKernel('/app'); + + $processor = new \Arcanum\Quill\CorrelationProcessor(); + + $bootstrapper = $this->createStub(Bootstrapper::class); + + $container = $this->createStub(Application::class); + $container->method('has')->willReturnCallback( + fn(string $id) => $id === \Arcanum\Quill\CorrelationProcessor::class, + ); + $container->method('get')->willReturnCallback( + fn(string $id) => match ($id) { + \Arcanum\Quill\CorrelationProcessor::class => $processor, + default => $bootstrapper, + }, + ); + $kernel->bootstrap($container); + + // Act + $kernel->handle($this->createStub(ServerRequestInterface::class)); + + // Assert — correlation ID was set during handle and cleared afterward + $this->assertNotNull($kernel->capturedRequest); + $this->assertNull( + (new \ReflectionProperty($processor, 'correlationId'))->getValue($processor), + 'Correlation ID should be cleared after handle()', + ); + } } diff --git a/tests/Ignition/RouteDispatcherTest.php b/tests/Ignition/RouteDispatcherTest.php index 0f00617..2ee3d16 100644 --- a/tests/Ignition/RouteDispatcherTest.php +++ b/tests/Ignition/RouteDispatcherTest.php @@ -19,6 +19,7 @@ use Psr\Http\Message\ServerRequestInterface; use Psr\Http\Server\MiddlewareInterface; use Psr\Http\Server\RequestHandlerInterface; +use Psr\Log\LoggerInterface; #[CoversClass(RouteDispatcher::class)] #[UsesClass(MiddlewareRegistry::class)] @@ -194,4 +195,33 @@ public function testWrapHttpBuildsMiddlewareStack(): void $result = $wrapped->handle($request); $this->assertSame($response, $result); } + + public function testDispatchLogsDispatchingDetails(): void + { + // Arrange + $dto = new \stdClass(); + $result = new \stdClass(); + $route = new Route(dtoClass: 'App\\Query\\Status', handlerPrefix: 'Get'); + + $bus = $this->createStub(Bus::class); + $bus->method('dispatch')->willReturn($result); + + $registry = new MiddlewareRegistry(); + $container = $this->createStub(ContainerInterface::class); + + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('debug') + ->with('Dispatching', [ + 'dto' => 'App\\Query\\Status', + 'handler_prefix' => 'Get', + 'before_middleware' => 0, + 'after_middleware' => 0, + ]); + + $dispatcher = new RouteDispatcher($container, $registry, $bus, $logger); + + // Act + $dispatcher->dispatch($dto, $route); + } } diff --git a/tests/Ignition/RuneKernelTest.php b/tests/Ignition/RuneKernelTest.php index 047673a..8f4cede 100644 --- a/tests/Ignition/RuneKernelTest.php +++ b/tests/Ignition/RuneKernelTest.php @@ -34,6 +34,7 @@ use Arcanum\Shodo\Formatters\TableFormatter; use Arcanum\Toolkit\Strings; use Psr\EventDispatcher\EventDispatcherInterface; +use Psr\Log\LoggerInterface; use PHPUnit\Framework\TestCase; use PHPUnit\Framework\Attributes\CoversClass; use PHPUnit\Framework\Attributes\UsesClass; @@ -56,6 +57,9 @@ #[UsesClass(CommandHandled::class)] #[UsesClass(CommandReceived::class)] #[UsesClass(TableFormatter::class)] +#[UsesClass(\Arcanum\Toolkit\Random::class)] +#[UsesClass(\Arcanum\Toolkit\Hex::class)] +#[UsesClass(\Arcanum\Quill\CorrelationProcessor::class)] final class RuneKernelTest extends TestCase { // --------------------------------------------------------------- @@ -625,6 +629,8 @@ private function containerWith( ExceptionHandler|null $exceptionHandler = null, EventDispatcherInterface|null $eventDispatcher = null, bool $withFormatRegistry = false, + LoggerInterface|null $logger = null, + \Arcanum\Quill\CorrelationProcessor|null $correlationProcessor = null, ): Application { $router = new CliRouter(new ConventionResolver(rootNamespace: $routeFixtureNamespace)); $hydrator = new Hydrator(); @@ -658,6 +664,8 @@ private function containerWith( ExceptionHandler::class => $exceptionHandler !== null, EventDispatcherInterface::class => $eventDispatcher !== null, CliFormatRegistry::class => $formatRegistry !== null, + LoggerInterface::class => $logger !== null, + \Arcanum\Quill\CorrelationProcessor::class => $correlationProcessor !== null, default => false, }, ); @@ -671,6 +679,9 @@ private function containerWith( ExceptionHandler::class => $exceptionHandler ?? throw new \RuntimeException('No handler'), EventDispatcherInterface::class => $eventDispatcher ?? throw new \RuntimeException('No dispatcher'), CliFormatRegistry::class => $formatRegistry ?? throw new \RuntimeException('No registry'), + LoggerInterface::class => $logger ?? throw new \RuntimeException('No logger'), + \Arcanum\Quill\CorrelationProcessor::class => + $correlationProcessor ?? throw new \RuntimeException('No processor'), default => throw new \RuntimeException("Unexpected service: $id"), }, ); @@ -689,4 +700,91 @@ private function bootstrapKernel(Application $container): RuneKernel $kernel->bootstrap($container); return $kernel; } + + // --------------------------------------------------------------- + // Lifecycle logging + // --------------------------------------------------------------- + + public function testHandleLogsCommandReceivedAndCompleted(): void + { + // Arrange + $bus = $this->createStub(Bus::class); + $bus->method('dispatch')->willReturn(new EmptyDTO()); + + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('debug') + ->with('Command received', ['command' => 'query:shop:products']); + $logger->expects($this->once()) + ->method('info') + ->with('Command completed', $this->callback( + fn(array $ctx) => $ctx['command'] === 'query:shop:products' + && $ctx['exit_code'] === 0, + )); + + $container = $this->containerWith(bus: $bus, logger: $logger); + $kernel = $this->bootstrapKernel($container); + + // Act + $kernel->handle(['bin/arcanum', 'query:shop:products']); + } + + public function testHandleLogsCompletedOnFailure(): void + { + // Arrange — route to a command that throws + $bus = $this->createStub(Bus::class); + $bus->method('dispatch')->willThrowException(new \RuntimeException('Boom')); + + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once())->method('debug'); + $logger->expects($this->once()) + ->method('info') + ->with('Command completed', $this->callback( + fn(array $ctx) => $ctx['exit_code'] === ExitCode::Failure->value, + )); + + $container = $this->containerWith(bus: $bus, logger: $logger); + $kernel = $this->bootstrapKernel($container); + + // Act + $kernel->handle(['bin/arcanum', 'query:shop:products']); + } + + public function testHandleSetsAndClearsCorrelationId(): void + { + // Arrange + $bus = $this->createStub(Bus::class); + $bus->method('dispatch')->willReturn(new EmptyDTO()); + + $processor = new \Arcanum\Quill\CorrelationProcessor(); + + $container = $this->containerWith(bus: $bus, correlationProcessor: $processor); + $kernel = $this->bootstrapKernel($container); + + // Act + $exitCode = $kernel->handle(['bin/arcanum', 'query:shop:products']); + + // Assert — correlation ID was set during handle and cleared afterward + $this->assertSame(0, $exitCode); + $this->assertNull( + (new \ReflectionProperty($processor, 'correlationId'))->getValue($processor), + 'Correlation ID should be cleared after handle()', + ); + } + + public function testHandleNoCommandSkipsLogging(): void + { + // Arrange — empty command shows splash, should not log + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->never())->method('debug'); + $logger->expects($this->never())->method('info'); + + $stdout = $this->createStream(); + $output = new ConsoleOutput($stdout, $this->createStream(), ansi: false); + $container = $this->containerWith(output: $output, logger: $logger); + $kernel = $this->bootstrapKernel($container); + + // Act + $kernel->handle(['bin/arcanum']); + } } diff --git a/tests/Quill/CorrelationProcessorTest.php b/tests/Quill/CorrelationProcessorTest.php new file mode 100644 index 0000000..204ed1e --- /dev/null +++ b/tests/Quill/CorrelationProcessorTest.php @@ -0,0 +1,107 @@ +makeRecord(); + + // Act + $result = $processor($record); + + // Assert + $this->assertSame($record, $result); + $this->assertArrayNotHasKey('correlation_id', $result->extra); + } + + public function testAddsCorrelationIdToExtra(): void + { + // Arrange + $processor = new CorrelationProcessor(); + $processor->setCorrelationId('abc123'); + $record = $this->makeRecord(); + + // Act + $result = $processor($record); + + // Assert + $this->assertSame('abc123', $result->extra['correlation_id']); + } + + public function testPreservesExistingExtra(): void + { + // Arrange + $processor = new CorrelationProcessor(); + $processor->setCorrelationId('abc123'); + $record = new LogRecord( + datetime: new \DateTimeImmutable(), + channel: 'test', + level: Level::Info, + message: 'test', + extra: ['existing' => 'value'], + ); + + // Act + $result = $processor($record); + + // Assert + $this->assertSame('value', $result->extra['existing']); + $this->assertSame('abc123', $result->extra['correlation_id']); + } + + public function testClearCorrelationIdStopsAddingIt(): void + { + // Arrange + $processor = new CorrelationProcessor(); + $processor->setCorrelationId('abc123'); + $processor->clearCorrelationId(); + $record = $this->makeRecord(); + + // Act + $result = $processor($record); + + // Assert + $this->assertSame($record, $result); + $this->assertArrayNotHasKey('correlation_id', $result->extra); + } + + public function testCorrelationIdCanBeChanged(): void + { + // Arrange + $processor = new CorrelationProcessor(); + $processor->setCorrelationId('first'); + $record1 = $this->makeRecord('first unit'); + + // Act + $result1 = $processor($record1); + $processor->setCorrelationId('second'); + $result2 = $processor($this->makeRecord('second unit')); + + // Assert + $this->assertSame('first', $result1->extra['correlation_id']); + $this->assertSame('second', $result2->extra['correlation_id']); + } +} diff --git a/tests/Session/SessionMiddlewareTest.php b/tests/Session/SessionMiddlewareTest.php index 725de93..450ad29 100644 --- a/tests/Session/SessionMiddlewareTest.php +++ b/tests/Session/SessionMiddlewareTest.php @@ -25,6 +25,7 @@ use Psr\Http\Message\ResponseInterface; use Psr\Http\Message\ServerRequestInterface; use Psr\Http\Server\RequestHandlerInterface; +use Psr\Log\LoggerInterface; #[CoversClass(SessionMiddleware::class)] #[UsesClass(Session::class)] @@ -219,4 +220,68 @@ public function testPersistsSessionDataAfterRequest(): void $this->assertSame(['msg' => 'Hello'], $data['_flash']); } + + // ----------------------------------------------------------- + // Logger instrumentation + // ----------------------------------------------------------- + + public function testLogsNewSessionStartedAndSaved(): void + { + // Arrange + $driver = new CacheSessionDriver(new ArrayDriver()); + $config = new SessionConfig(); + $registry = new ActiveSession(); + + $logger = $this->createMock(LoggerInterface::class); + $messages = []; + $logger->expects($this->exactly(2)) + ->method('debug') + ->willReturnCallback(function (string $message) use (&$messages): void { + $messages[] = $message; + }); + + $middleware = new SessionMiddleware($driver, $config, $registry, $logger); + + // Act + $middleware->process( + $this->stubRequest(), + $this->stubHandler($this->stubResponse()), + ); + + // Assert + $this->assertSame('Session started', $messages[0]); + $this->assertSame('Session saved', $messages[1]); + } + + public function testLogsExistingSessionLoaded(): void + { + // Arrange + $cache = new ArrayDriver(); + $driver = new CacheSessionDriver($cache); + $config = new SessionConfig(); + $registry = new ActiveSession(); + + $sessionId = SessionId::generate(); + $data = ['_identity' => '', '_csrf' => str_repeat('ab', 32), '_flash' => []]; + $driver->write($sessionId->value, $data, 3600); + + $logger = $this->createMock(LoggerInterface::class); + $messages = []; + $logger->expects($this->exactly(2)) + ->method('debug') + ->willReturnCallback(function (string $message) use (&$messages): void { + $messages[] = $message; + }); + + $middleware = new SessionMiddleware($driver, $config, $registry, $logger); + + // Act + $middleware->process( + $this->stubRequest(['arcanum_session' => $sessionId->value]), + $this->stubHandler($this->stubResponse()), + ); + + // Assert + $this->assertSame('Session loaded', $messages[0]); + } } diff --git a/tests/Throttle/RateLimiterTest.php b/tests/Throttle/RateLimiterTest.php index b9469ec..ab229b2 100644 --- a/tests/Throttle/RateLimiterTest.php +++ b/tests/Throttle/RateLimiterTest.php @@ -12,6 +12,7 @@ use PHPUnit\Framework\TestCase; use PHPUnit\Framework\Attributes\CoversClass; use PHPUnit\Framework\Attributes\UsesClass; +use Psr\Log\LoggerInterface; #[CoversClass(RateLimiter::class)] #[UsesClass(Quota::class)] @@ -51,4 +52,44 @@ public function testDelegatesLimitEnforcementToStrategy(): void $this->assertFalse($quota->isAllowed()); } + + public function testLogsRateCheckPassed(): void + { + // Arrange + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('debug') + ->with('Rate check passed', [ + 'key' => 'user-ip', + 'remaining' => 4, + ]); + + $limiter = new RateLimiter(new ArrayDriver(), new TokenBucket(), $logger); + + // Act + $limiter->attempt('user-ip', 5, 60); + } + + public function testLogsRateLimitExceeded(): void + { + // Arrange + $logger = $this->createMock(LoggerInterface::class); + $logger->expects($this->once()) + ->method('notice') + ->with('Rate limit exceeded', $this->callback(function (array $context): bool { + return $context['key'] === 'user-ip' + && $context['limit'] === 3 + && isset($context['retry_after']); + })); + + $limiter = new RateLimiter(new ArrayDriver(), new TokenBucket(), $logger); + + // Exhaust the limit + $limiter->attempt('user-ip', 3, 60); + $limiter->attempt('user-ip', 3, 60); + $limiter->attempt('user-ip', 3, 60); + + // Act — this attempt should be rejected + $limiter->attempt('user-ip', 3, 60); + } }