/logs: with `since`, only the newest `limit` records are returned, and the older ones are skipped for good #475

New issue

Closed

opened 2026-10-01 10:46:58 +00:00 by tiagoagueda · 0 comments

tiagoagueda commented

2026-10-01 10:46:58 +00:00

Owner

Found on 2026-09-29 in a read-only review of postulo at 95348908d, reading the log endpoint and running it against a log file of 500 records.

Related to #51.

Checked again on 2026-10-01 against main at 0a5cad587: still present.

/logs?since=… is documented as the way a collector asks only for what it has not seen, but the view takes the newest limit records first and filters by since afterwards. When more than limit records were written since the last poll, the collector receives the newest ones, takes the newest time as its next since, and the older records are never served. Nothing in the response says that anything was left out. The comparison is also a plain string comparison against whatever the caller sent, so a since with an offset other than +00:00, or one that is not a time at all, silently selects the wrong records.

Where: core/views_logs.py:97-108 (collect: records = logs.read(limit=limit, level=...), then records = [record for record in records if record.time > since]); core/logs.py:267-286 (read stops once len(found) >= limit, counting from the newest record).
What happens:
1. A collector polls every minute with since set to the last time it holds, as the wiki's Health, metrics and logs page describes, and no limit (so 200).
2. During that minute a failing notifier writes 500 records.
3. The response carries records 301 to 500; records 1 to 300, which include how the incident started, are never in any response.
Checked against the snapshot: 500 records 100 ms apart and since a minute before the first answered 200 lines, starting at the 301st record. since=2026-09-29T14:00:10+02:00 (the 11th second of the same run, written with an offset) answered no lines at all, and so did since=yesterday, both with 200.
Why it matters: the endpoint exists so that a collector off the host holds the instance's log. A burst is exactly when the log matters, and that is when the collector loses the start of it without any sign.
Fix: when since is given, read backwards until reaching a record at or before since, then return the oldest limit records after it, so a collector that polls again carries on from where it stopped rather than from the newest record. Parse since with datetime.fromisoformat and compare Record.when against it (a naive value read as UTC), answering 400 for a value that is not a time. Say in the wiki that a full page means there is more to fetch.

Done when

A test in tests/security/test_logs_endpoint.py writes 500 records, asks with since before the first and the default limit, and gets the oldest 200; asking again with the last time received gets the next 200.
A test in the same file asks with since written with a +02:00 offset and gets the records after that instant, and one with since=yesterday gets 400.

Found on 2026-09-29 in a read-only review of postulo at 95348908d, reading the log endpoint and running it against a log file of 500 records. Related to #51. Checked again on 2026-10-01 against `main` at `0a5cad587`: still present. `/logs?since=…` is documented as the way a collector asks only for what it has not seen, but the view takes the newest `limit` records first and filters by `since` afterwards. When more than `limit` records were written since the last poll, the collector receives the newest ones, takes the newest time as its next `since`, and the older records are never served. Nothing in the response says that anything was left out. The comparison is also a plain string comparison against whatever the caller sent, so a `since` with an offset other than `+00:00`, or one that is not a time at all, silently selects the wrong records. - **Where:** `core/views_logs.py:97-108` (`collect`: `records = logs.read(limit=limit, level=...)`, then `records = [record for record in records if record.time > since]`); `core/logs.py:267-286` (`read` stops once `len(found) >= limit`, counting from the newest record). - **What happens:** 1. A collector polls every minute with `since` set to the last `time` it holds, as the wiki's *Health, metrics and logs* page describes, and no `limit` (so 200). 2. During that minute a failing notifier writes 500 records. 3. The response carries records 301 to 500; records 1 to 300, which include how the incident started, are never in any response. Checked against the snapshot: 500 records 100 ms apart and `since` a minute before the first answered 200 lines, starting at the 301st record. `since=2026-09-29T14:00:10+02:00` (the 11th second of the same run, written with an offset) answered no lines at all, and so did `since=yesterday`, both with `200`. - **Why it matters:** the endpoint exists so that a collector off the host holds the instance's log. A burst is exactly when the log matters, and that is when the collector loses the start of it without any sign. - **Fix:** when `since` is given, read backwards until reaching a record at or before `since`, then return the oldest `limit` records after it, so a collector that polls again carries on from where it stopped rather than from the newest record. Parse `since` with `datetime.fromisoformat` and compare `Record.when` against it (a naive value read as UTC), answering `400` for a value that is not a time. Say in the wiki that a full page means there is more to fetch. ## Done when - A test in `tests/security/test_logs_endpoint.py` writes 500 records, asks with `since` before the first and the default `limit`, and gets the oldest 200; asking again with the last `time` received gets the next 200. - A test in the same file asks with `since` written with a `+02:00` offset and gets the records after that instant, and one with `since=yesterday` gets `400`.

tiagoagueda added this to the 0.6.0 milestone

2026-10-01 10:46:58 +00:00

tiagoagueda added the

observability

tier

bug

labels

2026-10-01 10:46:58 +00:00

tiagoagueda referenced this issue from a commit

2026-10-02 00:05:31 +00:00

Hand a collector the oldest records after its mark, not the newest

tiagoagueda closed this issue