Skip to content

Commit 24d7631

Browse files
committed
fix: Address review of the check_logfile bookmark option
Four things the review of #1406 turned up, all in the new bookmark path. An explicitly empty value (`bookmark=`) silently disabled bookmarking even though the documentation says an empty value means `auto`. The REST API renders a valueless parameter as a bare token so it never hit this, but the client-query path passes `k=v` through verbatim and a check written that way quietly went back to reporting the whole file on every run. The option now uses a notifier instead of binding a variable, which is what tells "given without a value" apart from "not given at all", and maps the empty value to `auto`. Positions moved as each file was read, so a check which failed on a later file - a second `file=` which cannot be opened - returned an error having already consumed the lines of the files before it, and nothing ever reported them. Positions are now collected and applied only once every file has been read. Nothing bounded the stored state. A bookmark name comes from the caller and an automatic one changes with the filter, so a host which generates names grew nsclient.db without end. Positions are now held in a bounded LRU map (1000 file/bookmark pairs); a position which ages out is dropped from the live set and blanked in the store on the next shutdown, and its file is simply read in full the next time that name appears. The automatic name also carries a hash of the filter, warning and critical expressions rather than the expressions themselves, so a filter of arbitrary length and content no longer ends up in the persisted key. Finally the documentation now covers what a bookmark costs: a line is consumed when the check runs rather than when its result is submitted, positions are saved on a clean shutdown so a crash re-reports the backlog, a file whose last line has no terminator never reports that line until something appends to it, and `${total}` counts the lines examined rather than the lines in the file. Assisted-by: Claude Code:claude-opus-5 Signed-off-by: Michael Medin <michael@medin.name>
1 parent b2a9897 commit 24d7631

9 files changed

Lines changed: 327 additions & 23 deletions

docs/samples/CheckLogFile_check_logfile_desc.md

Lines changed: 37 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -13,8 +13,9 @@ The name (`app-errors` above) identifies the stored position. Two checks that
1313
use the same name over the same file share one position — the first one to run
1414
consumes the lines. Use distinct names when two checks look for different
1515
things in the same file, or let the name be derived automatically by passing
16-
`bookmark` with no value (or `bookmark=auto`), which builds it from the file
17-
name plus the `filter`, `warning` and `critical` expressions:
16+
`bookmark` with no value (`bookmark`, `bookmark=` and `bookmark=auto` all mean
17+
the same thing), which builds it from the file name plus a hash of the
18+
`filter`, `warning` and `critical` expressions:
1819

1920
```
2021
check_logfile file=/var/log/app.log "filter=column1 like 'ERROR'" "warning=count > 0" bookmark
@@ -25,7 +26,7 @@ tracked on its own. They are written to `${data-path}/nsclient.db` when
2526
NSClient++ shuts down and restored on start, so a restart does not re-report
2627
everything.
2728

28-
Because an automatic name embeds the expressions, editing the filter starts a
29+
Because an automatic name covers the expressions, editing the filter starts a
2930
new position (and the file is read in full once more) and leaves the old one
3031
behind in the store. Prefer an explicit name for checks whose filter changes
3132
often, or which are generated with varying arguments.
@@ -46,13 +47,46 @@ Behaviour worth knowing:
4647
under a fixed name), the file is read from the beginning again. Rotation to a
4748
*different* name is not followed: point the check at the name that keeps
4849
receiving new lines.
50+
* **A failing check moves nothing.** If any of the files cannot be read the
51+
check returns an error and every position stays where it was, so the lines
52+
which were read on the way are reported by the next successful check instead
53+
of vanishing with the error.
4954
* **A quiet check is OK, not UNKNOWN.** When nothing new arrived the result is
5055
the empty state (`%(status): Nothing found`), which is OK by default; use
5156
`empty-state=` to change it.
5257
* **Checks without `bookmark` are unaffected.** They neither read nor advance
5358
any stored position, so an ad-hoc full scan can be run at any time without
5459
disturbing a bookmarked check.
5560

61+
Before you switch a check over to `bookmark`, know what you are trading a
62+
re-reported line for:
63+
64+
* **A line is consumed when the check runs, not when its result arrives.** With
65+
a bookmark the position moves as soon as the lines have been read. If the
66+
result is submitted passively (NSCA, NRDP, …) and that submission fails, the
67+
lines it described are not reported again by the next check. An actively
68+
polled check is not exposed to this: the position moves as the poller
69+
receives the answer.
70+
* **Positions are saved when NSClient++ shuts down.** A crash, a killed
71+
service or a power loss therefore rewinds every bookmark to where it was when
72+
the service last stopped cleanly, and the lines written since are reported
73+
again. They are never lost, only repeated.
74+
* **A last line without its terminator is never reported on its own.** This is
75+
the flip side of holding back half-written lines: a file which is written in
76+
one go and does not end with `line-split` keeps its final line unreported
77+
until something appends to the file. Without a bookmark that line is reported
78+
on every check as before.
79+
* **`${total}` counts what the check looked at.** With a bookmark that is the
80+
lines added since the previous run — not the number of lines in the file.
81+
`${count}` is, as always, how many of them matched the filter.
82+
* **The number of remembered positions is capped** (at 1000 file/bookmark
83+
pairs, which no ordinary configuration comes close to). If a host generates
84+
bookmark names — a script which puts a timestamp in the name, or automatic
85+
names for a filter which keeps changing — the least recently used positions
86+
are dropped, and the files they tracked are read in full the next time that
87+
name shows up. A dropped position is also cleared from `nsclient.db` on the
88+
next shutdown, so the store does not grow forever.
89+
5690
Real-time monitoring (`/settings/logfile/real-time/checks`) is the other way to
5791
get each line reported once; it pushes results as lines are written instead of
5892
being polled. `bookmark` is the polled equivalent and needs no configuration on

docs/samples/CheckLogFile_check_logfile_samples.md

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -52,6 +52,9 @@ check_logfile file=/var/log/app.log "filter=column1 like 'ERROR'" "warning=count
5252
3/5 (ERROR failed to connect to db, ERROR failed to connect to db, ERROR disk full)|'count'=3;0;0
5353
```
5454

55+
`bookmark=` (an empty value) and `bookmark=auto` are spelled differently by
56+
different transports but mean exactly this.
57+
5558
**Watch several files with one check**
5659

5760
Each file keeps its own position; the counts are aggregated. A fresh bookmark

modules/CheckLogFile/CheckLogFile.cpp

Lines changed: 42 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,7 @@
1515
#include <parsers/filter/cli_helper.hpp>
1616
#include <parsers/filter/modern_filter.hpp>
1717
#include <utility>
18+
#include <vector>
1819

1920
#include "bookmark_state.hpp"
2021
#include "file_reader.hpp"
@@ -58,9 +59,13 @@ bool CheckLogFile::loadModuleEx(std::string alias, NSCAPI::moduleLoadMode mode)
5859
thread_->filters_.add_samples(settings.get_settings());
5960

6061
// Restore the bookmark positions from the previous run so a restart does not
61-
// re-report every line of every bookmarked log file.
62+
// re-report every line of every bookmarked log file. An empty value is a
63+
// position which was retired on an earlier shutdown; it is remembered as a
64+
// key so it is not written again, but it is not a position.
6265
nscapi::core_helper core(get_core(), get_id());
6366
for (const nscapi::core_helper::storage_map::value_type &e : core.get_storage_strings(bookmark_context)) {
67+
if (e.second.empty()) continue;
68+
persisted_keys_.insert(e.first);
6469
bookmarks_.add(e.first, e.second);
6570
}
6671

@@ -73,9 +78,17 @@ bool CheckLogFile::unloadModule() {
7378
if (thread_ && !thread_->stop()) NSC_LOG_ERROR_STD("Failed to stop thread");
7479

7580
nscapi::core_helper core(get_core(), get_id());
76-
for (const check_logfile::bookmarks::map_type::value_type &v : bookmarks_.get_copy()) {
81+
const check_logfile::bookmarks::map_type live = bookmarks_.get_copy();
82+
for (const check_logfile::bookmarks::map_type::value_type &v : live) {
7783
core.put_storage(bookmark_context, v.first, v.second, false, false);
7884
}
85+
// A position which aged out of the (bounded) live set would otherwise keep
86+
// its row - and the file name and expression hash in its key - in
87+
// nsclient.db for good. The storage API has no delete, so blank the value:
88+
// load skips empty entries, which is the same as not having one.
89+
for (const std::string &key : persisted_keys_) {
90+
if (live.find(key) == live.end()) core.put_storage(bookmark_context, key, "", false, false);
91+
}
7992
return true;
8093
}
8194

@@ -189,17 +202,23 @@ void CheckLogFile::check_logfile(const PB::Commands::QueryRequestMessage::Reques
189202
"Notice that specifying multiple files will create an aggregate set it will not check each file individually.\n"
190203
"In other words if one file contains an error the entire check will result in error or if you check the count it is the global count which is used.")
191204
("files", po::value<std::string>(&files_string), "A comma separated list of files to scan (same as file except a list)")
192-
("bookmark", po::value<std::string>(&bookmark)->implicit_value("auto"),
205+
// Present-but-empty (`bookmark=`, which is how several transports render a
206+
// valueless argument) has to mean the same as the bare flag, or a check
207+
// written that way would silently stop being incremental. A notifier is
208+
// what makes the two tellable apart from "not given at all": with no
209+
// default_value it only runs when the option is actually supplied.
210+
("bookmark", po::value<std::string>()->implicit_value("auto")->notifier([&bookmark](const std::string &value) { bookmark = value.empty() ? "auto" : value; }),
193211
"Only scan lines added since the last check with the same bookmark name.\n"
194212
"NSClient++ remembers, per file and per bookmark, how far it read last time and resumes from there, "
195213
"so a line is reported once instead of on every check. The first check of a file reads it in full; "
196214
"a file which is truncated, rotated or replaced is detected (via its size and a fingerprint of its "
197215
"first bytes) and read from the beginning again. A trailing line which is not yet terminated by "
198216
"line-split is held back until it is complete, so half-written lines are never reported twice.\n"
199217
"If you set this to auto (or leave the value empty) the bookmark name is derived from the file name "
200-
"together with your filter, warning and critical expressions, which keeps unrelated checks of the "
201-
"same file from consuming each other's lines. Use an explicit name to share (or separate) positions "
202-
"deliberately. Positions are persisted across restarts.")
218+
"together with a hash of your filter, warning and critical expressions, which keeps unrelated checks "
219+
"of the same file from consuming each other's lines. Use an explicit name to share (or separate) "
220+
"positions deliberately. Positions are persisted when NSClient++ shuts down and restored on start; "
221+
"the newest ones are kept if more than a thousand accumulate.")
203222
("max-lines", po::value<std::size_t>(&max_lines)->default_value(0),
204223
"Only examine the newest <N> lines of each file (0, the default, means every line).\n"
205224
"The limit is applied per file, after any bookmark: with a bookmark the check still only sees lines "
@@ -255,13 +274,23 @@ void CheckLogFile::check_logfile(const PB::Commands::QueryRequestMessage::Reques
255274

256275
// An "auto" bookmark is derived from the file plus the expressions which
257276
// decide what is interesting, so two different checks over the same file do
258-
// not steal each other's lines (the same rule CheckEventLog uses).
277+
// not steal each other's lines (the same rule CheckEventLog uses). The
278+
// expressions go in as a hash rather than verbatim: the name ends up in the
279+
// persisted key, where a filter of arbitrary length (and content) has no
280+
// business being.
259281
std::string auto_suffix;
260282
if (bookmark == "auto") {
261-
auto_suffix = "],filter[" + str::utils::joinEx(filter_helper.data.filter_string, ",") + "],warn[" +
262-
str::utils::joinEx(filter_helper.data.warn_string, ",") + "],crit[" + str::utils::joinEx(filter_helper.data.crit_string, ",") + "]";
283+
const std::string expressions = "filter[" + str::utils::joinEx(filter_helper.data.filter_string, ",") + "],warn[" +
284+
str::utils::joinEx(filter_helper.data.warn_string, ",") + "],crit[" +
285+
str::utils::joinEx(filter_helper.data.crit_string, ",") + "]";
286+
auto_suffix = "],expr[" + check_logfile::bookmark::to_hex(check_logfile::bookmark::fnv1a(expressions.data(), expressions.size())) + "]";
263287
}
264288

289+
// Positions are moved only once every file has been read: a check which ends
290+
// in an error reports nothing, and lines it consumed on the way would be
291+
// lost with no way to get them back.
292+
std::vector<std::pair<std::string, std::string> > pending;
293+
265294
for (const std::string &filename : file_list) {
266295
std::ifstream file(filename.c_str(), std::ios::in | std::ios::binary);
267296
if (!file.is_open()) {
@@ -324,7 +353,10 @@ void CheckLogFile::check_logfile(const PB::Commands::QueryRequestMessage::Reques
324353
}
325354

326355
const check_logfile::bookmark::position next(decision.offset + consumed, head.size(), check_logfile::bookmark::fnv1a(head.data(), head.size()));
327-
bookmarks_.add(key, check_logfile::bookmark::format(next));
356+
pending.push_back(std::make_pair(key, check_logfile::bookmark::format(next)));
357+
}
358+
for (const std::pair<std::string, std::string> &p : pending) {
359+
bookmarks_.add(p.first, p.second);
328360
}
329361
filter_helper.post_process(filter);
330362
}

modules/CheckLogFile/CheckLogFile.h

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@
55

66
#include <nscapi/nscapi_plugin_impl.hpp>
77
#include <nscapi/protobuf/command.hpp>
8+
#include <set>
89

910
#include "bookmarks.hpp"
1011

@@ -13,6 +14,11 @@ class CheckLogFile : public nscapi::impl::simple_plugin {
1314
private:
1415
std::shared_ptr<real_time_thread> thread_;
1516
check_logfile::bookmarks bookmarks_;
17+
// Bookmark keys which were read from the core storage on load. A key which
18+
// is no longer live when we shut down is blanked out there, so a position
19+
// that has aged out (or whose filter was edited) does not keep its row in
20+
// nsclient.db forever.
21+
std::set<std::string> persisted_keys_;
1622

1723
public:
1824
CheckLogFile() {}

modules/CheckLogFile/bookmark_state.hpp

Lines changed: 87 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@
66
#include <cstddef>
77
#include <cstdint>
88
#include <cstdlib>
9+
#include <map>
910
#include <string>
1011
#include <vector>
1112

@@ -31,6 +32,18 @@ inline std::uint64_t fnv1a(const char *data, std::size_t len) {
3132
return hash;
3233
}
3334

35+
// 16 lowercase hex digits, used to name a bookmark after the expressions it
36+
// belongs to without spelling them out in the key.
37+
inline std::string to_hex(std::uint64_t value) {
38+
static const char digits[] = "0123456789abcdef";
39+
std::string ret(16, '0');
40+
for (std::size_t i = 0; i < 16; i++) {
41+
ret[15 - i] = digits[value & 0xf];
42+
value >>= 4;
43+
}
44+
return ret;
45+
}
46+
3447
// Where a previous check stopped reading a given file.
3548
//
3649
// `offset` is the end of the last COMPLETE record consumed, not the size of
@@ -142,5 +155,79 @@ inline resume_decision compute_resume(const position &prev, std::uint64_t cur_si
142155
return d;
143156
}
144157

158+
// Upper bound on the number of positions which are remembered (and hence
159+
// persisted to nsclient.db).
160+
//
161+
// A bookmark name comes from whoever runs the query, and an automatic name
162+
// changes whenever the filter does, so nothing stops a caller from creating a
163+
// new name on every check. Without a cap that grows the stored state - and the
164+
// file it is saved to - without bound. 1000 positions is far more than a real
165+
// configuration uses (it is per bookmark AND file) while staying small enough
166+
// to be irrelevant on disk.
167+
const std::size_t max_positions = 1000;
168+
169+
// A bounded, least-recently-used map of serialized positions.
170+
//
171+
// Not thread safe on its own - `check_logfile::bookmarks` wraps it in a lock.
172+
// Kept separate from that wrapper so the eviction rules can be unit tested
173+
// without a running module.
174+
class store {
175+
public:
176+
typedef std::map<std::string, std::string> map_type;
177+
178+
explicit store(std::size_t max_entries = max_positions) : max_entries_(max_entries == 0 ? 1 : max_entries), clock_(0) {}
179+
180+
void put(const std::string &key, const std::string &value) {
181+
entry &e = entries_[key];
182+
e.value = value;
183+
e.used = ++clock_;
184+
trim();
185+
}
186+
187+
// The stored value, or an empty string when the key is unknown. Counts as a
188+
// use: a bookmark which is checked but has nothing new to report must not
189+
// age out before one which is merely written to.
190+
std::string get(const std::string &key) {
191+
const impl_type::iterator it = entries_.find(key);
192+
if (it == entries_.end()) return "";
193+
it->second.used = ++clock_;
194+
return it->second.value;
195+
}
196+
197+
map_type snapshot() const {
198+
map_type ret;
199+
for (const impl_type::value_type &v : entries_) {
200+
ret[v.first] = v.second.value;
201+
}
202+
return ret;
203+
}
204+
205+
std::size_t size() const { return entries_.size(); }
206+
207+
private:
208+
struct entry {
209+
std::string value;
210+
// Monotonic use counter; the lowest one is the next to go.
211+
std::uint64_t used;
212+
entry() : used(0) {}
213+
};
214+
typedef std::map<std::string, entry> impl_type;
215+
216+
// Linear, but it only runs when the cap is exceeded and the cap is small.
217+
void trim() {
218+
while (entries_.size() > max_entries_) {
219+
impl_type::iterator oldest = entries_.begin();
220+
for (impl_type::iterator it = entries_.begin(); it != entries_.end(); ++it) {
221+
if (it->second.used < oldest->second.used) oldest = it;
222+
}
223+
entries_.erase(oldest);
224+
}
225+
}
226+
227+
std::size_t max_entries_;
228+
std::uint64_t clock_;
229+
impl_type entries_;
230+
};
231+
145232
} // namespace bookmark
146233
} // namespace check_logfile

0 commit comments

Comments
 (0)