jpmschweitzer/tatlock
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases 8 Wiki Activity

fix(logging): T-5 — production logs INFO to stdout

Browse Source 
docker logs tatlock has been empty for months and the /app/logs
mount untouched since 2025-12. Not a broken handler: the stdout
StreamHandler was correct all along, but the production default
level was WARNING ("minimal noise") and a healthy service warns
roughly never — startup, backend flavor detection and the wrapper's
balancing/compaction signals were all suppressed, which is exactly
what made the serving cutover unverifiable from logs on 2026-09-12.

Production now defaults to INFO; LOG_LEVEL stays the override for
when noise is ever the real problem; development keeps DEBUG. The
mount was always decorative — no file handler exists, docker logs is
the log. Three tests pin the level table, the WARNING-revert
mutation shown to fail its test.

Also filed T-7: the full suite flaked once and passed on rerun for
the second time — next occurrence keeps the failing run's output.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
jpmschweitzer
2026-09-13 11:00:50 +02:00
co-authored by Claude Fable 5
parent cbec26835d
commit aace128ef9
6 changed files with 62 additions and 3 deletions
Download Patch File Download Diff File Expand all files Collapse all files
.pql/changelog/ticket_history/2026-09.sql
+2
View File
@@ -5,3 +5,5 @@ INSERT INTO ticket_history (ticket_record_id, field, old_value, new_value, chang
Second finding 2026-09-13, from webber''s twin fix: an httpx event-hook on the client (the T-4 signal-reading approach) never fires under the openai SDK even when correctly wired — webber verified headers arriving while the hook stayed silent. When rewiring the client, read the signals from the parsed body''s model_extra in the sanitized create() instead (the wrapper injects balancing/compaction_due into non-streamed JSON bodies; openai pydantic models retain unknown fields). The steward''s raw-call body read is unaffected and already correct.', NULL, '2026-09-13 08:00:17', '2026-09-13 08:00:17.002', '2026-09-13 08:00:17.002', NULL, '6fb4cc1d7d7222e3d570cd8c7fed4fd9', 2) ON CONFLICT(hash) DO NOTHING;
INSERT INTO ticket_history (ticket_record_id, field, old_value, new_value, changed_by, changed_at, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06G9KH87TRDGW45GMDWVDRPABR', 'status', 'backlog', 'in_progress', NULL, '2026-09-13 08:19:35', '2026-09-13 08:19:35.028', '2026-09-13 08:19:35.028', NULL, '5bcf19379361a2f766cd4787ff734611', 2) ON CONFLICT(hash) DO NOTHING;
INSERT INTO ticket_history (ticket_record_id, field, old_value, new_value, changed_by, changed_at, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06G9KH87TRDGW45GMDWVDRPABR', 'status', 'in_progress', 'done', NULL, '2026-09-13 08:27:21', '2026-09-13 08:27:21.779', '2026-09-13 08:27:21.779', NULL, '1c59422336b88a76c6f1c3720916d7d5', 2) ON CONFLICT(hash) DO NOTHING;
INSERT INTO ticket_history (ticket_record_id, field, old_value, new_value, changed_by, changed_at, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06G99D07Z3FZY8EBT9PJ1RCGHW', 'status', 'backlog', 'in_progress', NULL, '2026-09-13 08:48:55', '2026-09-13 08:48:55.587', '2026-09-13 08:48:55.587', NULL, 'ca4f8fb42c961b0002aa87bb7b1d5af5', 2) ON CONFLICT(hash) DO NOTHING;
INSERT INTO ticket_history (ticket_record_id, field, old_value, new_value, changed_by, changed_at, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06G99D07Z3FZY8EBT9PJ1RCGHW', 'status', 'in_progress', 'done', NULL, '2026-09-13 09:00:50', '2026-09-13 09:00:50.006', '2026-09-13 09:00:50.006', NULL, '5ea799ee4815e42ede80c3df4c81b28c', 2) ON CONFLICT(hash) DO NOTHING;
.pql/changelog/ticket_idmap/2026-09.sql
+1
View File
@@ -2,3 +2,4 @@ INSERT INTO ticket_idmap (record_id, ticket_id, created_at, updated_at, deleted_
INSERT INTO ticket_idmap (record_id, ticket_id, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06G99D07EM5DZWTS0WD9V8PSKM', 'T-4', '2026-09-12 08:20:21.494', '2026-09-12 08:20:21.494', NULL, '5b28e07bdc3be1f9ed0ed71d2da60c72', 2) ON CONFLICT(record_id) DO UPDATE SET ticket_id=excluded.ticket_id, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= ticket_idmap.updated_at;
INSERT INTO ticket_idmap (record_id, ticket_id, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06G99D07Z3FZY8EBT9PJ1RCGHW', 'T-5', '2026-09-12 08:20:21.625', '2026-09-12 08:20:21.625', NULL, '0a417012779f612a4dad1a7dbd0787e3', 2) ON CONFLICT(record_id) DO UPDATE SET ticket_id=excluded.ticket_id, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= ticket_idmap.updated_at;
INSERT INTO ticket_idmap (record_id, ticket_id, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06G9KH87TRDGW45GMDWVDRPABR', 'T-6', '2026-09-13 07:57:01.782', '2026-09-13 07:57:01.782', NULL, 'd6c184ba6d24e03c0dc77064bf71fead', 2) ON CONFLICT(record_id) DO UPDATE SET ticket_id=excluded.ticket_id, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= ticket_idmap.updated_at;
INSERT INTO ticket_idmap (record_id, ticket_id, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06G9KZSCFR79G4DFCT4E5W5CAM', 'T-7', '2026-09-13 09:00:32.255', '2026-09-13 09:00:32.255', NULL, 'b0b0a4c3ccaabeb58ad1958e7c2c2602', 2) ON CONFLICT(record_id) DO UPDATE SET ticket_id=excluded.ticket_id, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= ticket_idmap.updated_at;
.pql/changelog/tickets/2026-09.sql
+3
View File
@@ -13,3 +13,6 @@ Second finding 2026-09-13, from webber''s twin fix: an httpx event-hook on the c
INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06G9KH87TRDGW45GMDWVDRPABR', 'bug', NULL, 'The sanitized OpenAI client is never used: the override pokes an attribute nobody reads', 'src/ollama/provider.py sets self._openai_client after super().__init__, but OllamaProvider.client serves self._client (pydantic_ai 1.27''s official openai_client= constructor param is the right wiring — webber hit the identical bug and fixed it 2026-09-13, exposed by the wrapper 503ing a session-less request). Silently dead in production as a result: the content-null sanitizer (moot on llama-server, live hazard if Ollama ever returns), the T-4 x-boilerroom-* signal hook (never logs), and the OLLAMA_TIMEOUT=120 cap (SDK default ~600s applies). Sessions were unaffected — they ride ModelSettings extra_body. Fix like webber: pass _SanitizedAsyncOpenAI through openai_client=, add a wiring test asserting provider.client is the sanitized type, then verify balancing/compaction logs actually appear.
Second finding 2026-09-13, from webber''s twin fix: an httpx event-hook on the client (the T-4 signal-reading approach) never fires under the openai SDK even when correctly wired — webber verified headers arriving while the hook stayed silent. When rewiring the client, read the signals from the parsed body''s model_extra in the sanitized create() instead (the wrapper injects balancing/compaction_due into non-streamed JSON bodies; openai pydantic models retain unknown fields). The steward''s raw-call body read is unaffected and already correct.', 'done', 'high', NULL, NULL, NULL, '2026-09-13 07:57:01.782', '2026-09-13 08:27:21.778', NULL, 'ce3151ff27c70a1028ba7c03b07119a2', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= tickets.updated_at;
INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06G99D07Z3FZY8EBT9PJ1RCGHW', 'bug', NULL, 'The container logs nowhere: stdout empty, /app/logs mount untouched', 'docker logs tatlock is 0 lines and the mounted ~/docker-data/tatlock/logs has been empty since 2025-12 — the running app writes logs to neither, which made the 2026-09-12 wrapper-cutover verification blind (flavor detection had to be proven behaviorally). Dev mode logs to build/logs/server.log via make run; production should log to stdout for docker logs at minimum.', 'in_progress', 'medium', NULL, NULL, NULL, '2026-09-12 08:20:21.624', '2026-09-13 08:48:55.586', NULL, '4770f6c6759cb82d825eb550dd4e42e2', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= tickets.updated_at;
INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06G9KZSCFR79G4DFCT4E5W5CAM', 'bug', NULL, 'The full suite flakes: one run fails, the rerun passes, twice now', 'Observed 2026-09-13 twice: before the v2.7.0 release audit and again during T-5 — make test exits 1 with a failure that does not reproduce on the immediate rerun, and both times the failing test''s name went uncaptured because the diagnostic rerun passed. Next occurrence: keep the FULL output of the failing run (make test 2>&1 | tee /tmp/flake.log) before rerunning, then pin the named test. Suspects worth checking when a name exists: order-dependent state in the session-scoped app init (conftest asyncio.run + cached health globals), port/redis contention with the live containers, and the coverage plugin''s tmp handling.', 'backlog', 'medium', NULL, NULL, NULL, '2026-09-13 09:00:32.255', '2026-09-13 09:00:32.255', NULL, '36c6f97b5a309e169b7acb35f7ca46d4', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= tickets.updated_at;
INSERT INTO tickets (record_id, type, parent_record_id, title, description, status, priority, assigned_to, team, decision_ref, created_at, updated_at, deleted_at, hash, canonical_version) VALUES ('06G99D07Z3FZY8EBT9PJ1RCGHW', 'bug', NULL, 'The container logs nowhere: stdout empty, /app/logs mount untouched', 'docker logs tatlock is 0 lines and the mounted ~/docker-data/tatlock/logs has been empty since 2025-12 — the running app writes logs to neither, which made the 2026-09-12 wrapper-cutover verification blind (flavor detection had to be proven behaviorally). Dev mode logs to build/logs/server.log via make run; production should log to stdout for docker logs at minimum.', 'done', 'medium', NULL, NULL, NULL, '2026-09-12 08:20:21.624', '2026-09-13 09:00:50.006', NULL, 'd04562943a55527d6036ec38c2657308', 2) ON CONFLICT(record_id) DO UPDATE SET type=excluded.type, parent_record_id=excluded.parent_record_id, title=excluded.title, description=excluded.description, status=excluded.status, priority=excluded.priority, assigned_to=excluded.assigned_to, team=excluded.team, decision_ref=excluded.decision_ref, updated_at=excluded.updated_at, deleted_at=excluded.deleted_at, hash=excluded.hash, canonical_version=excluded.canonical_version WHERE excluded.updated_at >= tickets.updated_at;
CHANGELOG.md
+12
View File
@@ -7,6 +7,18 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
## [Unreleased]
### Fixed
- Production logs exist now (T-5): the production default log level
was WARNING ("minimal noise"), and a healthy service warns roughly
never — so `docker logs tatlock` was empty for months, startup,
backend flavor detection and the wrapper's balancing/compaction
signals all suppressed, and the serving cutover could not be
verified from logs. The production default is INFO on stdout;
`LOG_LEVEL` remains the override for when noise is ever the real
problem. (The `/app/logs` mount was always decorative — no file
handler exists; `docker logs` is the log.)
## [2.7.1] - 2026-09-13
### Fixed
src/core/config.py
+9 -3
View File
@@ -230,15 +230,21 @@ class Config(BaseSettings):
Get effective log level, auto-determining from environment if not set.
- development: DEBUG (maximum verbosity)
- production: WARNING (minimal noise)
- production: INFO
- testing: INFO
Production ran at WARNING ("minimal noise") until T-5: a healthy
service warns roughly never, so `docker logs` was empty for
months — startup, backend flavor detection and the wrapper's
balancing/compaction signals all suppressed, which made the
2026-09-12 serving cutover unverifiable from logs. INFO on
stdout is the operational floor; LOG_LEVEL quiets it when noise
ever becomes the real problem.
"""
if self.LOG_LEVEL is not None:
return self.LOG_LEVEL
if self.ENVIRONMENT == Environment.DEVELOPMENT:
return "DEBUG"
if self.ENVIRONMENT == Environment.PRODUCTION:
return "WARNING"
return "INFO"
@property
tests/core/test_logging_config.py
+35
View File
@@ -241,6 +241,41 @@ class TestLoggingConfiguration:
with patch.object(config, "ENVIRONMENT", Environment.PRODUCTION):
assert config.log_format == "json"
def test_production_default_level_is_info(self):
"""Production logs INFO to stdout (T-5).
The old WARNING default made `docker logs` empty for months — a
healthy service warns roughly never, so startup, flavor
detection and the wrapper signals were all suppressed and the
serving cutover could not be verified from logs.
"""
from src.core.config import Environment, config
with (
patch.object(config, "ENVIRONMENT", Environment.PRODUCTION),
patch.object(config, "LOG_LEVEL", None),
):
assert config.effective_log_level == "INFO"
def test_log_level_env_still_quiets_production(self):
"""LOG_LEVEL stays the override for when noise is the problem."""
from src.core.config import Environment, config
with (
patch.object(config, "ENVIRONMENT", Environment.PRODUCTION),
patch.object(config, "LOG_LEVEL", "WARNING"),
):
assert config.effective_log_level == "WARNING"
def test_development_default_stays_debug(self):
from src.core.config import Environment, config
with (
patch.object(config, "ENVIRONMENT", Environment.DEVELOPMENT),
patch.object(config, "LOG_LEVEL", None),
):
assert config.effective_log_level == "DEBUG"
def test_multiple_loggers_independent(self):
"""Test multiple loggers are independent."""
logger1 = get_logger("test.logger1")