fix(logs): a line with no RouterOS id had no protection against re-insertion (v0.24.4-beta)
Follows #137. The v0.24.1 fix made the count honest and stopped a thousand round trips per poll, but it assumed the unique index on (device_id, log_id) would reject lines already stored. For most devices it does. For a device whose log entries carry no `.id` it never could: the column was set to NULL, and PostgreSQL treats NULLs as *distinct* in a unique index, so every NULL conflicts with nothing. Those devices re-inserted their entire buffer on every poll, for ever, and the constraint that was supposed to stop it was structurally incapable of firing. A line with no id now gets a key derived from its own content -- timestamp, topics and message -- so the existing index does the work. The `#` prefix keeps it out of the space of real RouterOS ids (`*` plus hex), so the two cannot collide, and parseRosId already rejects it, which matters because the watermark is a max over real ids and must not be poisoned by a synthetic one. The trade, stated rather than buried: two genuinely separate lines sharing a timestamp, topic and message collapse into one. RouterOS timestamps are second-resolution, so that can happen. Losing a repeat of an identical message is a much smaller loss than growing the table by the whole buffer every minute without bound. This was found by reading a comment on #137 I had not read before closing it -- log output from a device with eleven lines total, reporting eleven new entries every minute for forty-five minutes. My own fleet cannot reproduce it: every event here carries a real `.id`, with no nulls and no duplicates, which is exactly why the hole was invisible from here. So this closes a defect demonstrable from the schema; whether it is the whole of that reporter's problem is still an open question and the issue is reopened to ask. Verified no regression where ids are healthy: no surrogate keys generated, no nulls, no duplicates, and counts that vary with real activity. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
This commit is contained in:
co-authored by
Claude Opus 5
parent
6bc7480b89
commit
d9fa120abc
@@ -30,7 +30,7 @@ const UPDATE_DOWNLOAD_TIMEOUT_MS = 10 * 60_000;
|
||||
* learned to abandon a timed-out connection, desynchronised the session (#137).
|
||||
*/
|
||||
const LOG_READ_TIMEOUT_MS = 120_000;
|
||||
import { selectNewLogLines, highestStoredId, type RawLogLine } from '../../utils/logDedup';
|
||||
import { selectNewLogLines, highestStoredId, surrogateLogId, type RawLogLine } from '../../utils/logDedup';
|
||||
import { alertService } from '../AlertService';
|
||||
|
||||
/** DB column limits for topology_links (see migrate.ts); reject oversize rows instead of silent truncation. */
|
||||
@@ -852,17 +852,23 @@ export class DeviceCollector {
|
||||
|
||||
const pending: unknown[][] = [];
|
||||
for (const log of fresh) {
|
||||
const logId = (log['.id'] || '') as string;
|
||||
const rawId = (log['.id'] || '') as string;
|
||||
const topics = (log['topics'] as string) || '';
|
||||
const message = (log['message'] as string) || '';
|
||||
const time = this.parseLogTime(log['time'] || '');
|
||||
const severity = this.mapLogSeverity((log['topics'] as string) || '');
|
||||
const severity = this.mapLogSeverity(topics);
|
||||
// Never store a null log_id: the unique index that stops re-insertion
|
||||
// does not constrain nulls, so a device whose lines carry no `.id`
|
||||
// would accumulate the same entries for ever (#137).
|
||||
const logId = rawId || surrogateLogId(log['time'] || '', topics, message);
|
||||
pending.push([
|
||||
this.device.id,
|
||||
time.toISOString(),
|
||||
severity,
|
||||
(log['topics'] as string) || null,
|
||||
(log['message'] as string) || '',
|
||||
topics || null,
|
||||
message,
|
||||
JSON.stringify(log),
|
||||
logId || null,
|
||||
logId,
|
||||
]);
|
||||
}
|
||||
|
||||
|
||||
@@ -1,5 +1,6 @@
|
||||
import {
|
||||
parseRosId, highestStoredId, isLogReset, selectNewLogLines, type RawLogLine,
|
||||
parseRosId, highestStoredId, isLogReset, selectNewLogLines,
|
||||
surrogateLogId, isSurrogateLogId, type RawLogLine,
|
||||
} from '../logDedup';
|
||||
|
||||
// Fixed clock so timestamp comparisons are deterministic.
|
||||
@@ -91,3 +92,49 @@ describe('selectNewLogLines', () => {
|
||||
expect(selectNewLogLines(logs, { lastStoredId: 0, latestStoredTime, parseTime })).toHaveLength(0);
|
||||
});
|
||||
});
|
||||
|
||||
describe('surrogateLogId', () => {
|
||||
const line = ['sep/08 02:38:10', 'system,info', 'router rebooted'] as const;
|
||||
|
||||
it('is stable for the same line', () => {
|
||||
expect(surrogateLogId(...line)).toBe(surrogateLogId(...line));
|
||||
});
|
||||
|
||||
it('differs when any field differs', () => {
|
||||
const base = surrogateLogId(...line);
|
||||
expect(surrogateLogId('sep/08 02:38:11', line[1], line[2])).not.toBe(base);
|
||||
expect(surrogateLogId(line[0], 'system,error', line[2])).not.toBe(base);
|
||||
expect(surrogateLogId(line[0], line[1], 'something else')).not.toBe(base);
|
||||
});
|
||||
|
||||
// Field boundaries are separated, so shifting text between fields cannot
|
||||
// produce the same key.
|
||||
it('does not confuse field boundaries', () => {
|
||||
expect(surrogateLogId('a', 'b', 'c')).not.toBe(surrogateLogId('ab', '', 'c'));
|
||||
});
|
||||
|
||||
// The column is VARCHAR(20); an over-long key would throw on insert.
|
||||
it('fits the log_id column', () => {
|
||||
const id = surrogateLogId('x'.repeat(500), 'y'.repeat(500), 'z'.repeat(5000));
|
||||
expect(id.length).toBeLessThanOrEqual(20);
|
||||
});
|
||||
|
||||
it('cannot be mistaken for a RouterOS id', () => {
|
||||
const id = surrogateLogId(...line);
|
||||
expect(id.startsWith('#')).toBe(true);
|
||||
expect(isSurrogateLogId(id)).toBe(true);
|
||||
expect(isSurrogateLogId('*CC75')).toBe(false);
|
||||
expect(isSurrogateLogId(null)).toBe(false);
|
||||
});
|
||||
|
||||
/**
|
||||
* The watermark is a max over RouterOS's own hex ids. A synthesised id must
|
||||
* not be parsed as one, or it would poison the high-water mark and make every
|
||||
* real line look already-seen.
|
||||
*/
|
||||
it('is ignored by the id watermark', () => {
|
||||
const id = surrogateLogId(...line);
|
||||
expect(parseRosId(id)).toBe(0);
|
||||
expect(highestStoredId([id, '*10'])).toBe(0x10);
|
||||
});
|
||||
});
|
||||
|
||||
@@ -7,6 +7,8 @@
|
||||
* the entire buffer once a minute.
|
||||
*/
|
||||
|
||||
import { createHash } from 'crypto';
|
||||
|
||||
export interface RawLogLine {
|
||||
'.id'?: string;
|
||||
time?: string;
|
||||
@@ -81,3 +83,35 @@ export function selectNewLogLines(
|
||||
}
|
||||
return out;
|
||||
}
|
||||
|
||||
/**
|
||||
* A stable identifier for a log line that RouterOS gave no `.id`.
|
||||
*
|
||||
* The events table has a unique index on (device_id, log_id) and relies on it
|
||||
* to reject lines already stored. PostgreSQL treats NULLs as *distinct* in a
|
||||
* unique index, so a NULL log_id conflicts with nothing: a device whose log
|
||||
* entries carry no `.id` had no protection at all and re-inserted the same
|
||||
* lines on every poll, without bound.
|
||||
*
|
||||
* Deriving the key from the line's own content restores that protection. The
|
||||
* `#` prefix keeps it out of the space of real RouterOS ids, which are `*`
|
||||
* followed by hex, so the two can never collide or be mistaken for each other.
|
||||
*
|
||||
* The trade, stated plainly: two genuinely separate lines with the same
|
||||
* timestamp, topic and text collapse into one. RouterOS timestamps are
|
||||
* second-resolution, so that is possible. Losing a repeat of an identical
|
||||
* message is a far smaller loss than growing the table by the whole buffer
|
||||
* every minute for ever.
|
||||
*/
|
||||
export function surrogateLogId(time: string, topics: string, message: string): string {
|
||||
const hash = createHash('sha256')
|
||||
.update(`${time}\u0000${topics}\u0000${message}`)
|
||||
.digest('hex')
|
||||
.slice(0, 16);
|
||||
return `#${hash}`; // 17 chars, inside the column's VARCHAR(20)
|
||||
}
|
||||
|
||||
/** True for the ids this module synthesised, as opposed to RouterOS's own. */
|
||||
export function isSurrogateLogId(id: string | null | undefined): boolean {
|
||||
return typeof id === 'string' && id.startsWith('#');
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user