moonming opened a new pull request, #14192:
URL: https://github.com/apache/apisix/pull/14192
### Description
`execute_func` in `apisix/utils/batch-processor.lua` calls a logger's batch
callback directly. When the callback raises an error instead of returning
`false, err`, the timer is aborted (`lua entry thread aborted: runtime error:
...`), the batch skips the retry policy, and its entries are never added to
`processed_entries`.
Since #13826 the backlog limit is on by default (`max_pending_entries`,
8192), and the backlog is computed as `total_pushed_entries - processed
entries`. Every entry of a batch whose callback raised therefore stays
"pending" for the rest of the worker's life. Once 8192 of them have
accumulated, the worker discards every new entry of that logger, and neither
fixing the log server nor changing the route brings it back; only a reload or
restart does. Before 3.18 the same leak happened only when
`max_pending_entries` was configured.
Reproduced with the `apache/apisix:3.19.0-debian` image, whose batch
processor files are identical to master: `splunk-hec-logging` with its default
batch settings, pointed at an endpoint that answers `403
{"message":"Forbidden"}` (the nil concatenation in #14011), with
`worker_processes: 1`.
| | before | with this PR |
|---|---|---|
| 9,499 requests while the endpoint answers 403 | 9 batches abort with
`attempt to concatenate field 'text'`; the log then shows
`total_pushed_entries: 8192 total_processed_entries: 0` and entries are
discarded | 10 batches fail through the normal path (`Batch
Processor[splunk-hec-logging] failed to process entries: ...`); nothing is
discarded |
| endpoint changed to one that answers 200, then 300 more requests | no
batch reaches it; entries are still discarded | the batch is delivered |
This PR:
1. Calls the callback through `pcall`. A raised error is handled like a
`false` return, so the batch is retried according to `max_retry_count` and
counted as processed when it is dropped. The error is logged in the existing
`failed to process entries: <err>` line.
2. Counts a batch as processed when its timer cannot be created (`failed to
create process timer: ...`, e.g. `too many pending timers`). That was the other
path that dropped a batch without counting it, with the same effect on the
backlog.
3. Adds one sentence to the batch processor docs (en and zh) saying that a
callback that raises is treated as a failed batch.
Per-plugin fixes such as #14012 are still useful for clearer error messages,
but with this change a bug in one logger's callback can no longer turn that
logger off for the rest of the worker's life.
#### Tests
- `t/utils/batch-processor.t` TEST 14: a callback that raises is called
again on retry and is then dropped with `exceeded the max_retry_count`,
`processed_entries` becomes 1, and no `lua entry thread aborted` is logged.
- `t/utils/batch-processor.t` TEST 15: when `ngx.timer.at` fails, the
dropped batch is counted in `processed_entries`.
- `t/utils/batch-processor-manager.t` TEST 8: with `max_pending_entries =
2`, two entries whose callback raised do not block the next two entries.
All three tests fail on master and pass with this change.
`t/utils/batch-processor.t` and `t/utils/batch-processor-manager.t` (90 tests)
pass locally, and a set of logger plugin test files gives the same results with
and without the change (details below). `lj-releng` and `reindex` pass;
`luacheck` was not run locally and relies on CI.
#### Notes for reviewers
- A raising callback is now retried like a failing one. For a deterministic
error the retries are wasted work, but they are bounded by `max_retry_count`
(default 0), which is the same as for a callback that returns `false` for a
deterministic reason.
- The uncaught error used to come with a stack trace; it is now logged as
the error message only, which still carries the file and line of the throw.
#### Which issue(s) this PR fixes:
Related to #14011, #14012, #14003, #14004
### Checklist
- [x] I have explained the need for this PR and the problem it solves
- [x] I have explained the changes or the new features added to this PR
- [x] I have added tests corresponding to this change
- [x] I have updated the documentation to reflect this change (one sentence
in the batch processor docs, en and zh)
- [x] I have verified that this change is backward compatible (If not,
please discuss on the [APISIX mailing
list](https://github.com/apache/apisix/tree/master#community) first)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
