Logging

ac-cli/src/main/resources/agenticcode.properties

@@ -4,4 +4,4 @@
 server.url=http://localhost:8787
 # Stamped by manage-ac.sh (stamp_cli_version) from ac-code-server's agenticcode.version
 # at build time. "dev" means this jar wasn't built via manage-ac.sh.
-version=165
+version=166

x-docs/roadmap.md

@@ -281,6 +281,44 @@ before. The parked "parallel parse phase" idea was implemented 2026-07-18 (item
   means "the refresh is done", not "the ingest is done". Per-module `refreshModule` is deliberately
   left alone: it is short, called often, and would only add noise.
 
+- [x] **113. Every server operation logs when it finishes** (done 2026-08-06, extends 112)
+
+  Rule applied: **an operation that logs a start must log an end.** Four violated it.
+
+  **The access log was already there — its duration was just never recorded.** Every request has
+  been logged as `POST /api/projects/upms/refresh?deep=true -> 200 (-ms)`; the `(-ms)` is not a
+  missing feature but `quarkus.http.record-request-start-time` defaulting to `false`, so
+  `%{RESPONSE_TIME}` has nothing to render. Setting it gives *every* endpoint a completion line with
+  a real duration for one property and one `System.nanoTime()` per request. It adds no new log lines
+  — the access log already covered every call. The property lives in `VertxHttpConfig`, not
+  `VertxHttpBuildTimeConfig`, i.e. it is a **runtime** property, so it does not have to be repeated
+  in the test-side `application.properties`.
+
+  **Two domain completion lines, both at the shared worker rather than the entry points:**
+
+  - `ProjectIngestService.ingestRoot` → `Project ingest finished: project=…, mode=tier1|call_graph|full,
+    files=…, persisted=…, failed=…, duplicates=…, N s` — covers project create, the call-graph pass
+    and the deep whole-root pass.
+  - `ProjectIngestService.bfsIngest` → `Deep ingest finished: project=…, seed=…, files=…, failed=…,
+    unresolved=…, truncated=…, N s`.
+
+  `bfsIngest` is the single worker behind **both** `ingestModules` (by name) and `ingestFiles` (the
+  fan-out warm). Lines first written into `DeepIngestCoordinator` at the two call sites were removed
+  again once that was traced — they would have double-logged every deep ingest. The `files` count is
+  per operation, deliberately: the walk emits one `Ingesting <module> …` start line *per file*, so
+  the single end line is what those N start lines add up to.
+
+  **No `try/finally` with an `outcome` flag**, though the proposal called for one. All three sites
+  already log their failure path (`Fan-out warm … failed`, `Auto deep-ingest … failed`, and an
+  `ingestRoot` exception surfacing as a 500 *with duration* once the access log works). Buying
+  symmetry would have meant restructuring the definite-assignment flow of a 90-line method on the hot
+  ingest path for a log line — a bad trade.
+
+  A refresh now logs two lines by design: `Project ingest finished` (parse + persist) and `Refresh
+  finished` (item 112, additionally covering the deleted-file sweep). The difference between them is
+  the sweep's cost, which was not visible anywhere before. `refreshModule` stays silent — short,
+  frequent, pure noise.
+
 ## Known bugs
 
 - [x] **107. Every module endpoint answers `200` with an empty shell for a module that does not exist —