diff --git a/README.md b/README.md index 5e34f14..4c1d8dc 100644 --- a/README.md +++ b/README.md @@ -6,7 +6,7 @@

- Version + Version License Docker TypeScript diff --git a/backend/package.json b/backend/package.json index f39fecf..6426ae8 100644 --- a/backend/package.json +++ b/backend/package.json @@ -1,6 +1,6 @@ { "name": "mikrotik-manager-backend", - "version": "0.24.0-beta", + "version": "0.24.1-beta", "description": "Mikrotik Network Management Platform - Backend API", "main": "dist/index.js", "scripts": { diff --git a/backend/src/index.ts b/backend/src/index.ts index 92e5990..804055c 100644 --- a/backend/src/index.ts +++ b/backend/src/index.ts @@ -7,6 +7,7 @@ import morgan from 'morgan'; import { createServer } from 'http'; import { Server as SocketServer } from 'socket.io'; import { Client as SshClient } from 'ssh2'; +import { resolveAuth, type SshExecDevice } from './services/sshExec'; import type { ClientChannel } from 'ssh2'; import dotenv from 'dotenv'; @@ -30,7 +31,6 @@ import { rateLimitRedis } from './middleware/rateLimitRedis'; import { initSecrets } from './utils/secrets'; import { reencryptStaleCredentials } from './db/reencryptCredentials'; import { reconcileStaleGuards } from './services/changeGuard/ChangeGuard'; -import { decrypt } from './utils/crypto'; import { corsMiddlewareOptions, socketIoCorsOptions } from './utils/corsOrigins'; import authRoutes from './routes/auth'; @@ -189,23 +189,28 @@ terminalNs.on('connection', (socket) => { socket.emit('error', 'Too many terminal sessions started. Please wait a moment and try again.'); return; } - const device = await queryOne<{ - ip_address: string; - ssh_port: number | null; - ssh_username: string | null; - ssh_password_encrypted: string | null; - }>( - `SELECT ip_address, ssh_port, ssh_username, ssh_password_encrypted FROM devices WHERE id = $1`, + const device = await queryOne( + `SELECT id, name, ip_address, ssh_port, ssh_username, ssh_password_encrypted, + api_username, api_password_encrypted + FROM devices WHERE id = $1`, [deviceId] ); if (!device) { socket.emit('error', 'Device not found'); return; } - if (!device.ssh_username || !device.ssh_password_encrypted) { - socket.emit('error', 'No SSH credentials configured for this device. Add an SSH username and password in device settings.'); + + // Resolve credentials the same way every other SSH consumer does, so a + // deployed key works here too. Doing this locally, and looking only at + // the stored password, is what broke the console once a key replaced the + // password (#133). + let auth: Awaited>; + try { + auth = await resolveAuth(device); + } catch (e) { + socket.emit('error', + `${(e as Error).message}. Add an SSH username and password in device settings, ` + + `or deploy an SSH key for this device.`); return; } - - const password = decrypt(device.ssh_password_encrypted); sshClient = new SshClient(); sshClient.on('ready', () => { @@ -214,7 +219,7 @@ terminalNs.on('connection', (socket) => { (err, stream) => { if (err) { socket.emit('error', err.message); return; } shellStream = stream; - auditTerminal(user, clientIp, `opened SSH shell on device ${deviceId} (${device.ip_address})`, deviceId); + auditTerminal(user, clientIp, `opened SSH shell on device ${deviceId} (${device.ip_address}) using ${auth.kind} auth`, deviceId); socket.emit('ready'); stream.on('data', (data: Buffer) => { @@ -238,8 +243,8 @@ terminalNs.on('connection', (socket) => { sshClient.connect({ host: device.ip_address, port: device.ssh_port ?? 22, - username: device.ssh_username, - password, + username: auth.username, + ...auth.auth, readyTimeout: 10_000, algorithms: { kex: [ diff --git a/backend/src/routes/firmware.ts b/backend/src/routes/firmware.ts index fa93ab0..294ad08 100644 --- a/backend/src/routes/firmware.ts +++ b/backend/src/routes/firmware.ts @@ -77,6 +77,41 @@ router.post('/rollouts', requireWrite, async (req: Request, res: Response) => { } if (scheduled_at && isNaN(Date.parse(scheduled_at))) return res.status(400).json({ error: 'scheduled_at must be a valid timestamp' }); + // Refuse before creating anything (#139). The rollout used to be written + // first and started second, so a rejected start left the rows behind: the + // user saw "already running", pressed again, and each press quietly banked + // another rollout for the same devices. Nothing is persisted unless the + // request can actually be honoured. + const busy = await query<{ device_id: number; name: string; rollout_id: number }>( + `SELECT frd.device_id, d.name, frd.rollout_id + FROM firmware_rollout_devices frd + JOIN firmware_rollouts r ON r.id = frd.rollout_id + JOIN devices d ON d.id = frd.device_id + WHERE frd.device_id = ANY($1::int[]) + AND r.status IN ('pending','running') + AND frd.status NOT IN ('success','failed','skipped')`, + [devices.map((d) => d.device_id)] + ); + if (busy.length > 0) { + const names = [...new Set(busy.map((b) => b.name))]; + return res.status(409).json({ + error: + `${names.join(', ')} ${names.length === 1 ? 'is' : 'are'} already part of ` + + `rollout #${busy[0].rollout_id}, which has not finished. ` + + `Wait for it to complete or cancel it first.`, + conflicting_rollout_id: busy[0].rollout_id, + device_ids: [...new Set(busy.map((b) => b.device_id))], + }); + } + // An immediate start needs the orchestrator free; a scheduled one does not. + if (start && !scheduled_at && firmwareOrchestrator.running) { + return res.status(409).json({ + error: `Rollout #${firmwareOrchestrator.running} is still running. ` + + `Wait for it to finish, or schedule this one for later.`, + conflicting_rollout_id: firmwareOrchestrator.running, + }); + } + const rollout = await queryOne<{ id: number }>( `INSERT INTO firmware_rollouts (name, halt_on_failure, pre_backup, routerboot_after, scheduled_at) VALUES ($1,$2,$3,$4,$5) RETURNING id`, @@ -89,7 +124,12 @@ router.post('/rollouts', requireWrite, async (req: Request, res: Response) => { if (start && !scheduled_at) { try { await firmwareOrchestrator.start(rollout!.id); } - catch (e) { return res.status(409).json({ error: (e as Error).message, id: rollout!.id }); } + catch (e) { + // Lost a race for the orchestrator. Remove the rollout we just created + // rather than leaving an unstartable shell behind. + await query(`DELETE FROM firmware_rollouts WHERE id = $1`, [rollout!.id]).catch(() => {}); + return res.status(409).json({ error: (e as Error).message }); + } } res.status(201).json({ id: rollout!.id }); }); diff --git a/backend/src/services/FirmwareOrchestrator.ts b/backend/src/services/FirmwareOrchestrator.ts index 4052595..86ba808 100644 --- a/backend/src/services/FirmwareOrchestrator.ts +++ b/backend/src/services/FirmwareOrchestrator.ts @@ -188,16 +188,37 @@ export class FirmwareOrchestrator { const freeMb = Math.round((parseInt(res['free-hdd-space'] || '0', 10) / 1048576) * 10) / 10; const spaceNote = freeMb > 0 ? ` The device reports ${freeMb} MB free.` : ''; - await collector.downloadUpdate(); - - // Wait for the device to say the image has landed. Large images on slow - // links take minutes, and the old fixed 25-second guess is what made this - // look like a failure while the device was still working. - const dlDeadline = Date.now() + DOWNLOAD_TIMEOUT_MS; + // The download command blocks until the image has landed, which on an + // ordinary link is a minute or more. If that outruns its budget the + // connection can no longer be trusted, so it is replaced rather than + // reused -- but a timed-out download is *not* evidence of failure. The + // device is asked on a fresh connection what actually happened, because + // declaring failure here is what made a working download look broken + // when several devices ran in one wave (#136). let downloaded = false; + try { + await collector.downloadUpdate(DOWNLOAD_TIMEOUT_MS); + } catch (e) { + console.warn(`[Firmware] ${device.name}: download command did not return cleanly ` + + `(${(e as Error).message}); re-checking on a new connection`); + collector.disconnect(); + try { + await collector.connect(); + } catch (re) { + return fail( + `Lost contact with the device while downloading ${latest}: ${(re as Error).message}. ` + + `Nothing was rebooted.${spaceNote}` + ); + } + } + + // Confirm the image is on the device. Normally this is true immediately, + // because the download command only returns once it is; the wait covers + // RouterOS versions that return early and report progress instead. + const dlDeadline = Date.now() + DOWNLOAD_TIMEOUT_MS; while (Date.now() < dlDeadline) { if (this.cancelRequested) break; - const s = await collector.getUpdateStatus(); + const s = await collector.getUpdateStatus().catch(() => ''); if (/downloaded/i.test(s)) { downloaded = true; break; } if (/error|fail/i.test(s)) { collector.disconnect(); diff --git a/backend/src/services/mikrotik/DeviceCollector.ts b/backend/src/services/mikrotik/DeviceCollector.ts index 1fee020..1e75079 100644 --- a/backend/src/services/mikrotik/DeviceCollector.ts +++ b/backend/src/services/mikrotik/DeviceCollector.ts @@ -19,6 +19,18 @@ import { import { bytesSince, periodKey, shouldSend } from '../../utils/dataCap'; import { parseDeviceLogTime } from '../../utils/deviceTime'; import { BackupService } from '../BackupService'; + +/** RouterOS update commands reach out to MikroTik's servers and are slow by nature. */ +const UPDATE_CHECK_TIMEOUT_MS = 90_000; +const UPDATE_DOWNLOAD_TIMEOUT_MS = 10 * 60_000; +/** + * `/log/print` returns the device's entire ring buffer -- a thousand sentences + * is normal -- and measured against real hardware it routinely outruns the 30s + * default. Timing it out cost the device's whole log *and*, before the client + * 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 { alertService } from '../AlertService'; /** DB column limits for topology_links (see migrate.ts); reject oversize rows instead of silent truncation. */ @@ -800,22 +812,21 @@ export class DeviceCollector { async collectEvents(): Promise { try { - const logs = await this.client.execute('/log/print'); + const logs = await this.client.execute( + '/log/print', {}, [], { timeoutMs: LOG_READ_TIMEOUT_MS } + ); if (!logs.length) return; - // RouterOS log .id values are hex strings like "*1A2F". Parse to int for comparison. - const parseRosId = (id: string): number => { - const hex = (id || '').replace(/^\*/, ''); - return hex ? parseInt(hex, 16) : 0; - }; - - // Find the highest RouterOS log ID we've already stored for this device. - const lastRow = await queryOne<{ log_id: string }>( + // The highest id we hold, taken across recent rows rather than from the + // single most recently inserted one. Those are usually the same, but when + // they differ the watermark slips backwards and the entire buffer looks + // new on every poll (#137). + const storedIds = await query<{ log_id: string }>( `SELECT log_id FROM events WHERE device_id = $1 AND log_id IS NOT NULL AND log_id != '' - ORDER BY id DESC LIMIT 1`, + ORDER BY id DESC LIMIT 2000`, [this.device.id] ); - const lastIdNum = parseRosId(lastRow?.log_id || ''); + const lastIdNum = highestStoredId(storedIds.map((r) => r.log_id)); // Always get the latest stored event time — needed for timestamp fallback. const latestStored = await queryOne<{ event_time: Date }>( @@ -824,45 +835,55 @@ export class DeviceCollector { ); const latestTime = latestStored?.event_time ? new Date(latestStored.event_time) : new Date(0); - // Detect log buffer overflow or device reboot: if all current IDs are below - // our stored lastIdNum, RouterOS has cleared/reset its log buffer. - // In that case, fall back to timestamp-based deduplication to avoid missing events. - const currentIds = logs.map(l => parseRosId(l['.id'] || '')).filter(id => id > 0); - const maxCurrentId = currentIds.length > 0 ? Math.max(...currentIds) : 0; - const logReset = lastRow && maxCurrentId > 0 && maxCurrentId < lastIdNum; + + // Collect the candidates first, then insert them in batches. + // + // This used to issue one INSERT per line and count every attempt as new, + // so a poll that re-read the whole ring buffer and inserted nothing still + // reported "Collected 1000 new log entries" — a thousand round trips a + // minute per device, described as work that had not happened (#137). + // Counting what the database actually accepted makes the log line true + // and the duplicate case cheap. + const fresh = selectNewLogLines(logs as RawLogLine[], { + lastStoredId: lastIdNum, + latestStoredTime: latestTime, + parseTime: (raw) => this.parseLogTime(raw), + }); + + const pending: unknown[][] = []; + for (const log of fresh) { + const logId = (log['.id'] || '') as string; + const time = this.parseLogTime(log['time'] || ''); + const severity = this.mapLogSeverity((log['topics'] as string) || ''); + pending.push([ + this.device.id, + time.toISOString(), + severity, + (log['topics'] as string) || null, + (log['message'] as string) || '', + JSON.stringify(log), + logId || null, + ]); + } let newCount = 0; - for (const log of logs) { - const logId = (log['.id'] || '') as string; - const logIdNum = parseRosId(logId); - - if (logId && !logReset) { - // Primary: skip entries already stored by RouterOS ID - if (logIdNum <= lastIdNum) continue; - } else { - // Fallback: no .id field, or log buffer has been reset — use timestamp deduplication - const time = this.parseLogTime(log['time'] || ''); - if (time <= latestTime) continue; - } - - const time = this.parseLogTime(log['time'] || ''); - const severity = this.mapLogSeverity(log['topics'] || ''); - - await query( + const COLS = 7; + const BATCH = 200; + for (let i = 0; i < pending.length; i += BATCH) { + const chunk = pending.slice(i, i + BATCH); + const values = chunk + .map((_, r) => `(${Array.from({ length: COLS }, (_, c) => `$${r * COLS + c + 1}`).join(',')})`) + .join(','); + // RETURNING reports only the rows actually written; ON CONFLICT rows are + // silently dropped, which is exactly the count we want. + const inserted = await query<{ id: number }>( `INSERT INTO events (device_id, event_time, severity, topic, message, raw_json, log_id) - VALUES ($1,$2,$3,$4,$5,$6,$7) - ON CONFLICT (device_id, log_id) DO NOTHING`, - [ - this.device.id, - time.toISOString(), - severity, - log['topics'] || null, - log['message'] || '', - JSON.stringify(log), - logId || null, - ] + VALUES ${values} + ON CONFLICT (device_id, log_id) DO NOTHING + RETURNING id`, + chunk.flat() ); - newCount++; + newCount += inserted.length; } if (newCount > 0) { @@ -3757,12 +3778,16 @@ export class DeviceCollector { // ─── Firmware updates ───────────────────────────────────────────────────── async checkForUpdates(): Promise> { - await this.client.execute('/system/package/update/check-for-updates').catch(() => {}); - // Give the device a moment to complete the check + // Reaches out to MikroTik's servers, so it can outlast the ordinary read + // timeout on a slow or filtered link. The failure was previously swallowed + // (.catch(() => {})), which hid a timed-out check and left the caller + // reading whatever /print happened to return (#136). + await this.client.execute( + '/system/package/update/check-for-updates', {}, [], { timeoutMs: UPDATE_CHECK_TIMEOUT_MS } + ); + // Give the device a moment to settle the result before reading it back. await new Promise((resolve) => setTimeout(resolve, 3000)); - const result = await this.client - .execute('/system/package/update/print') - .catch(() => [] as Record[]); + const result = await this.client.execute('/system/package/update/print'); return (result[0] as Record) || {}; } @@ -3776,8 +3801,11 @@ export class DeviceCollector { * be observed — and on at least one CCR it neither downloaded nor rebooted * while reporting nothing at all (#firmware). */ - async downloadUpdate(): Promise { - await this.client.execute('/system/package/update/download'); + async downloadUpdate(timeoutMs = UPDATE_DOWNLOAD_TIMEOUT_MS): Promise { + // Blocks until the image has landed -- a minute or more is normal, and the + // 30-second default read timeout was cutting it off and corrupting the + // connection (#136). + await this.client.execute('/system/package/update/download', {}, [], { timeoutMs }); } /** The `status` line from /system/package/update, e.g. "Downloaded, please reboot…". */ diff --git a/backend/src/services/mikrotik/RouterOSClient.ts b/backend/src/services/mikrotik/RouterOSClient.ts index 47e7501..876b66e 100644 --- a/backend/src/services/mikrotik/RouterOSClient.ts +++ b/backend/src/services/mikrotik/RouterOSClient.ts @@ -40,6 +40,8 @@ export class RouterOSClient extends EventEmitter { timeout: ReturnType; } | null = null; private sentenceQueue: RouterOSSentence[] = []; + /** Set when a reply stream can no longer be trusted; distinct from `connected`. */ + private poisoned = false; private tagCounter = 0; @@ -62,6 +64,10 @@ export class RouterOSClient extends EventEmitter { async connect(): Promise { if (this.connected) return; + // A fresh connection starts trusted, so a client that was abandoned earlier + // can be reconnected and used again. + this.poisoned = false; + this.sentenceQueue = []; await new Promise((resolve, reject) => { const timer = setTimeout(() => { @@ -124,10 +130,18 @@ export class RouterOSClient extends EventEmitter { } // Enqueue a command so concurrent calls don't interleave + /** + * @param opts.timeoutMs How long to wait for each reply sentence. The 30s + * default suits ordinary reads, but some RouterOS commands legitimately run + * far longer -- `/system/package/update/download` takes a minute or more on + * an ordinary link -- and timing those out corrupted the connection (#136). + * Callers issuing a long-running command must say so. + */ async execute( command: string, params: Record = {}, - queries: string[] = [] + queries: string[] = [], + opts: { timeoutMs?: number } = {} ): Promise[]> { let result!: Record[]; let error!: Error; @@ -135,7 +149,7 @@ export class RouterOSClient extends EventEmitter { await new Promise((resolve) => { this.operationChain = this.operationChain.then(async () => { try { - result = await this._executeRaw(command, params, queries); + result = await this._executeRaw(command, params, queries, opts.timeoutMs); } catch (err) { error = err as Error; } @@ -150,7 +164,8 @@ export class RouterOSClient extends EventEmitter { private async _executeRaw( command: string, params: Record, - queries: string[] + queries: string[], + timeoutMs?: number ): Promise[]> { if (!this.socket || !this.connected) { throw new RouterOSError('Not connected'); @@ -168,7 +183,7 @@ export class RouterOSClient extends EventEmitter { const results: Record[] = []; while (true) { - const sentence = await this.readNextSentence(); + const sentence = await this.readNextSentence(timeoutMs); if (sentence.type === '!done') break; if (sentence.type === '!re') { results.push(sentence.words); @@ -341,6 +356,17 @@ export class RouterOSClient extends EventEmitter { const sentence = this.tryParseSentence(); if (!sentence) break; + // Once a connection is abandoned, anything still arriving belongs to the + // command that gave up. Queueing it would hand it to the next caller as + // that caller's own reply, which is the desynchronisation poison() exists + // to prevent -- destroying the socket usually stops this, but data already + // buffered can still surface. + // + // This must test `poisoned`, not `connected`: `connected` is only set once + // login has *finished*, so testing it here discarded the login exchange + // itself and every connection timed out. + if (this.poisoned) continue; + if (this.pendingRead) { clearTimeout(this.pendingRead.timeout); const { resolve } = this.pendingRead; @@ -425,6 +451,19 @@ export class RouterOSClient extends EventEmitter { return new Promise((resolve, reject) => { const timer = setTimeout(() => { this.pendingRead = null; + // A timed-out read leaves a reply in flight. Previously the socket was + // left open, so when that reply finally arrived processBuffer() found no + // pending read and queued it -- and the *next* command took it as its + // own answer. Every later command on that connection then returned the + // previous one's data. + // + // That is how a slow `/system/package/update/download` turned into + // "did not finish downloading within 10 minutes" (#136): the status + // polls afterwards were reading shifted replies and could never see + // "Downloaded". A desynchronised connection can also make an unrelated + // command look like it succeeded, so the only safe response is to stop + // using it. + this.poison('Read timeout waiting for API response'); reject(new RouterOSError('Read timeout waiting for API response')); }, timeoutMs); @@ -436,6 +475,22 @@ export class RouterOSClient extends EventEmitter { }); } + /** + * Abandon a connection whose reply stream can no longer be trusted. + * + * Anything already queued belongs to a command that gave up, so it is + * discarded rather than handed to the next caller. + */ + private poison(reason: string): void { + this.poisoned = true; + this.connected = false; + this.sentenceQueue = []; + this.buffer = Buffer.alloc(0); + try { this.socket?.destroy(); } catch { /* already gone */ } + this.socket = null; + this.emit('poisoned', reason); + } + // Execute a streaming/generator command (one that never sends !done on its own, // e.g. /tool/ip-scan). Collects !re rows until maxDurationMs elapses, then // sends /cancel to terminate the command and drains the cleanup response. diff --git a/backend/src/services/mikrotik/__tests__/RouterOSClient.test.ts b/backend/src/services/mikrotik/__tests__/RouterOSClient.test.ts index de35cb7..38a310c 100644 --- a/backend/src/services/mikrotik/__tests__/RouterOSClient.test.ts +++ b/backend/src/services/mikrotik/__tests__/RouterOSClient.test.ts @@ -77,3 +77,91 @@ describe('sentence parsing', () => { expect(REPEATED_KEY).toBe(REPEATED_ATTRIBUTES_KEY); }); }); + +/** + * Read-timeout handling (#136). + * + * A timed-out read leaves a reply in flight. The connection used to stay open, + * so when that reply eventually arrived it was queued and handed to the *next* + * command as its own answer — every subsequent call on that connection returned + * the previous one's data. + * + * That is what turned a slow `/system/package/update/download` into "did not + * finish downloading within 10 minutes": the status polls afterwards were + * reading shifted replies and could never see "Downloaded". The same + * desynchronisation could make any unrelated command appear to succeed, so + * these tests matter well beyond firmware. + */ +describe('read timeout', () => { + type Internals = { + buffer: Buffer; + connected: boolean; + socket: unknown; + sentenceQueue: RouterOSSentence[]; + pendingRead: unknown; + readNextSentence(timeoutMs?: number): Promise; + processBuffer(): void; + }; + + const makeClient = () => { + const client = new RouterOSClient('127.0.0.1', 8728, 'x', 'x'); + const internals = client as unknown as Internals; + internals.connected = true; + internals.socket = { destroy() {} }; + return { client, internals }; + }; + + // The regression these were written without: the discard guard first tested + // `connected`, which is only set *after* login succeeds. Every login reply was + // therefore thrown away and every connection timed out — the whole fleet went + // offline. The tests above all pre-set connected = true, so none of them saw + // it. "Not yet connected" and "abandoned" are different states. + it('delivers replies that arrive before login has completed', () => { + const { internals } = makeClient(); + internals.connected = false; // mid-login, as connect() leaves it + internals.buffer = sentence('ret=abc123'); + internals.processBuffer(); + expect(internals.sentenceQueue).toHaveLength(1); + }); + + it('rejects when no reply arrives in time', async () => { + const { internals } = makeClient(); + await expect(internals.readNextSentence(20)).rejects.toThrow(/Read timeout/); + }); + + it('does not hand a late reply to the next command', async () => { + const { internals } = makeClient(); + + await expect(internals.readNextSentence(20)).rejects.toThrow(/Read timeout/); + + // The reply the timed-out command was waiting for now turns up. + internals.buffer = sentence('status=Downloaded, please reboot'); + internals.processBuffer(); + + // It must not be sitting in the queue waiting to be mistaken for the next + // command's answer. + expect(internals.sentenceQueue).toHaveLength(0); + }); + + it('marks the connection unusable so it cannot be reused blind', async () => { + const { client, internals } = makeClient(); + await expect(internals.readNextSentence(20)).rejects.toThrow(/Read timeout/); + + expect(internals.connected).toBe(false); + // A caller that carries on regardless gets a clean error rather than + // another command's data. + await expect(client.execute('/system/resource/print')).rejects.toThrow(/Not connected/); + }); + + // The guard above must not break ordinary pipelining: a healthy connection + // legitimately queues replies that arrive faster than they are read. + it('still serves queued replies while the connection is healthy', async () => { + const { internals } = makeClient(); + internals.buffer = sentence('status=ok'); + internals.processBuffer(); + expect(internals.sentenceQueue).toHaveLength(1); + await expect(internals.readNextSentence(20)).resolves.toMatchObject({ + words: { status: 'ok' }, + }); + }); +}); diff --git a/backend/src/services/sshExec.ts b/backend/src/services/sshExec.ts index cf7c665..2f120db 100644 --- a/backend/src/services/sshExec.ts +++ b/backend/src/services/sshExec.ts @@ -13,6 +13,7 @@ import { Client as SSHClient } from 'ssh2'; import { queryOne } from '../config/database'; import { decrypt } from '../utils/crypto'; +import { preferredAuth, type KeyStatus } from '../utils/sshKeys'; export interface SshExecDevice { id: number; @@ -39,19 +40,33 @@ const DEFAULT_TIMEOUT_MS = 30_000; * * A key is used only when it has been *proved* — a key that was generated or * pushed but never authenticated is not evidence the device will accept it. + * + * Exported because every SSH consumer must agree on this. The interactive + * terminal used to resolve credentials itself, looked only at the stored + * password, and so broke the moment a key was deployed and the password + * retired — the exact workflow the key feature exists to enable (#133). */ -async function resolveAuth(device: SshExecDevice): Promise<{ +export async function resolveAuth(device: SshExecDevice): Promise<{ username: string; auth: { password: string } | { privateKey: string }; kind: 'key' | 'password'; }> { - const key = await queryOne<{ private_key_encrypted: string; ssh_username: string | null }>( - `SELECT private_key_encrypted, ssh_username FROM device_ssh_keys - WHERE device_id = $1 AND status = 'verified'`, + const key = await queryOne<{ + private_key_encrypted: string; ssh_username: string | null; status: KeyStatus; + }>( + `SELECT private_key_encrypted, ssh_username, status FROM device_ssh_keys + WHERE device_id = $1`, [device.id] ); - if (key) { + const encryptedPassword = device.ssh_password_encrypted || device.api_password_encrypted; + const choice = preferredAuth( + key?.status ?? null, + !!key?.private_key_encrypted, + !!encryptedPassword + ); + + if (choice === 'key' && key) { const username = key.ssh_username || device.ssh_username || device.api_username; if (!username) throw new Error('No SSH username available for key authentication'); return { username, auth: { privateKey: decrypt(key.private_key_encrypted) }, kind: 'key' }; @@ -59,9 +74,8 @@ async function resolveAuth(device: SshExecDevice): Promise<{ const username = device.ssh_username || device.api_username; if (!username) throw new Error('No SSH username configured'); - const encrypted = device.ssh_password_encrypted || device.api_password_encrypted; - if (!encrypted) throw new Error('No SSH credential configured'); - return { username, auth: { password: decrypt(encrypted) }, kind: 'password' }; + if (choice === 'none' || !encryptedPassword) throw new Error('No SSH credential configured'); + return { username, auth: { password: decrypt(encryptedPassword) }, kind: 'password' }; } /** diff --git a/backend/src/utils/__tests__/logDedup.test.ts b/backend/src/utils/__tests__/logDedup.test.ts new file mode 100644 index 0000000..2f9d204 --- /dev/null +++ b/backend/src/utils/__tests__/logDedup.test.ts @@ -0,0 +1,93 @@ +import { + parseRosId, highestStoredId, isLogReset, selectNewLogLines, type RawLogLine, +} from '../logDedup'; + +// Fixed clock so timestamp comparisons are deterministic. +const T = (iso: string) => new Date(iso); +const parseTime = (raw: string) => (raw ? T(raw) : new Date(0)); + +const line = (id: string, time = '', message = 'm'): RawLogLine => + ({ '.id': id, time, message, topics: 'system,info' }); + +describe('parseRosId', () => { + it('reads RouterOS hex ids', () => { + expect(parseRosId('*1A2F')).toBe(0x1a2f); + expect(parseRosId('1a2f')).toBe(0x1a2f); + }); + + it('returns 0 for anything unusable', () => { + for (const bad of ['', undefined, '*', '*zz', 'not-hex', '*-5']) { + expect(parseRosId(bad as string)).toBe(0); + } + }); +}); + +describe('highestStoredId', () => { + // The bug this exists for: taking the last *inserted* row instead of the + // highest id lets the watermark move backwards, after which every line looks + // new and the whole buffer is reprocessed every poll. + it('takes the maximum, not the last element', () => { + expect(highestStoredId(['*10', '*FF', '*20'])).toBe(0xff); + }); + + it('ignores nulls and junk', () => { + expect(highestStoredId([null, undefined, '', '*zz', '*7'])).toBe(7); + expect(highestStoredId([])).toBe(0); + }); +}); + +describe('isLogReset', () => { + it('detects ids going backwards', () => { + expect(isLogReset(5, 900)).toBe(true); + }); + + it('is not fooled by a first run or an empty buffer', () => { + expect(isLogReset(900, 0)).toBe(false); + expect(isLogReset(0, 900)).toBe(false); + }); + + it('treats normal forward movement as no reset', () => { + expect(isLogReset(950, 900)).toBe(false); + }); +}); + +describe('selectNewLogLines', () => { + const latestStoredTime = T('2026-09-08T00:00:00Z'); + + it('returns nothing when the whole buffer is already stored', () => { + // The reported symptom: a thousand lines re-offered every minute. + const logs = Array.from({ length: 1000 }, (_, i) => line(`*${(i + 1).toString(16)}`)); + const out = selectNewLogLines(logs, { lastStoredId: 1000, latestStoredTime, parseTime }); + expect(out).toHaveLength(0); + }); + + it('returns only the lines above the watermark', () => { + const logs = [line('*8'), line('*9'), line('*A'), line('*B')]; + const out = selectNewLogLines(logs, { lastStoredId: 9, latestStoredTime, parseTime }); + expect(out.map((l) => l['.id'])).toEqual(['*A', '*B']); + }); + + it('falls back to timestamps when the buffer has reset', () => { + // Ids went backwards, so they cannot be compared against the watermark. + const logs = [ + line('*1', '2026-09-07T23:00:00Z'), // older than what we hold + line('*2', '2026-09-08T00:30:00Z'), // newer + ]; + const out = selectNewLogLines(logs, { lastStoredId: 900, latestStoredTime, parseTime }); + expect(out.map((l) => l['.id'])).toEqual(['*2']); + }); + + it('uses timestamps for lines carrying no id', () => { + const logs = [ + { time: '2026-09-07T23:00:00Z', message: 'old' }, + { time: '2026-09-08T01:00:00Z', message: 'new' }, + ]; + const out = selectNewLogLines(logs, { lastStoredId: 5, latestStoredTime, parseTime }); + expect(out.map((l) => l.message)).toEqual(['new']); + }); + + it('treats a line exactly on the boundary as already stored', () => { + const logs = [{ time: '2026-09-08T00:00:00Z', message: 'boundary' }]; + expect(selectNewLogLines(logs, { lastStoredId: 0, latestStoredTime, parseTime })).toHaveLength(0); + }); +}); diff --git a/backend/src/utils/__tests__/sshKeys.test.ts b/backend/src/utils/__tests__/sshKeys.test.ts index 7eb67f4..54e71bd 100644 --- a/backend/src/utils/__tests__/sshKeys.test.ts +++ b/backend/src/utils/__tests__/sshKeys.test.ts @@ -67,7 +67,8 @@ describe('preferredAuth', () => { // bound to them, confirmed on hardware by removing the key and watching // password login start working again. expect(preferredAuth('verified', true, true)).toBe('key'); - expect(preferredAuth('deployed', true, true)).toBe('key'); + // Pushed but never proved: not yet evidence the device will accept it. + expect(preferredAuth('deployed', true, true)).toBe('password'); }); it('uses the password only when no key is installed', () => { diff --git a/backend/src/utils/logDedup.ts b/backend/src/utils/logDedup.ts new file mode 100644 index 0000000..ce53d57 --- /dev/null +++ b/backend/src/utils/logDedup.ts @@ -0,0 +1,83 @@ +/** + * Deciding which RouterOS log lines are actually new (issue #137). + * + * `/log/print` returns the device's whole ring buffer every time — commonly a + * thousand lines — so almost all of it is already stored. Getting this decision + * right is the difference between inserting a handful of rows and re-offering + * the entire buffer once a minute. + */ + +export interface RawLogLine { + '.id'?: string; + time?: string; + topics?: string; + message?: string; + [k: string]: unknown; +} + +/** RouterOS log ids are hex strings like "*1A2F"; 0 means "no usable id". */ +export function parseRosId(id: string | undefined): number { + const hex = (id || '').replace(/^\*/, ''); + if (!hex || !/^[0-9a-fA-F]+$/.test(hex)) return 0; + const n = parseInt(hex, 16); + return Number.isSafeInteger(n) && n > 0 ? n : 0; +} + +/** + * The highest log id we have already stored. + * + * Taken as the maximum over recent rows rather than "the last row inserted". + * Those are usually the same, but not always — and when they differ the + * watermark goes backwards, every later line looks new, and the whole buffer is + * reprocessed on every poll. + */ +export function highestStoredId(storedIds: (string | null | undefined)[]): number { + let max = 0; + for (const id of storedIds) { + const n = parseRosId(id ?? undefined); + if (n > max) max = n; + } + return max; +} + +/** + * Has the device's log buffer been cleared or the device rebooted? + * + * Detected by ids going backwards. When it happens the id watermark is + * meaningless and timestamps are the only thing left to compare. + */ +export function isLogReset(currentMaxId: number, lastStoredId: number): boolean { + return lastStoredId > 0 && currentMaxId > 0 && currentMaxId < lastStoredId; +} + +/** + * Which lines should be inserted. + * + * `parseTime` is injected so the caller's RouterOS timestamp handling is used + * without this module needing to know about it. + */ +export function selectNewLogLines( + logs: RawLogLine[], + opts: { + lastStoredId: number; + latestStoredTime: Date; + parseTime: (raw: string) => Date; + } +): RawLogLine[] { + const ids = logs.map((l) => parseRosId(l['.id'])).filter((n) => n > 0); + const currentMax = ids.length ? Math.max(...ids) : 0; + const reset = isLogReset(currentMax, opts.lastStoredId); + + const out: RawLogLine[] = []; + for (const log of logs) { + const id = parseRosId(log['.id']); + if (id > 0 && !reset) { + if (id <= opts.lastStoredId) continue; + } else { + // No usable id, or the buffer reset: fall back to timestamps. + if (opts.parseTime(log.time || '') <= opts.latestStoredTime) continue; + } + out.push(log); + } + return out; +} diff --git a/backend/src/utils/sshKeys.ts b/backend/src/utils/sshKeys.ts index 950282e..a55fe22 100644 --- a/backend/src/utils/sshKeys.ts +++ b/backend/src/utils/sshKeys.ts @@ -96,13 +96,19 @@ export type KeyStatus = 'pending' | 'deployed' | 'verified' | 'failed'; * * The real recovery path is the binary API, which is unaffected by any of this * and can always remove the key. + * + * Only a *verified* key counts. One that was generated or pushed but never + * authenticated is not evidence the device will accept it, and 'deployed' is a + * transient state on the way to being proved. This function previously admitted + * it, which disagreed with the resolver that actually ran -- the disagreement + * went unnoticed because nothing outside these tests ever called this (#133). */ export function preferredAuth( status: KeyStatus | null, hasPrivateKey: boolean, hasPassword: boolean, ): 'key' | 'password' | 'none' { - if (hasPrivateKey && (status === 'verified' || status === 'deployed')) return 'key'; + if (hasPrivateKey && status === 'verified') return 'key'; if (hasPassword) return 'password'; return 'none'; } diff --git a/frontend/package.json b/frontend/package.json index a3d1f0e..68d2d57 100644 --- a/frontend/package.json +++ b/frontend/package.json @@ -1,6 +1,6 @@ { "name": "mikrotik-manager-frontend", - "version": "0.24.0-beta", + "version": "0.24.1-beta", "private": true, "type": "module", "scripts": { diff --git a/frontend/src/pages/FirmwarePage.tsx b/frontend/src/pages/FirmwarePage.tsx index cd1544c..134d469 100644 --- a/frontend/src/pages/FirmwarePage.tsx +++ b/frontend/src/pages/FirmwarePage.tsx @@ -48,9 +48,22 @@ function RolloutPanel({ rolloutId, canWrite }: { rolloutId: number; canWrite: bo }, }); + // The API answers a cancel with a note explaining that the device currently + // being upgraded is never interrupted mid-write. That note was discarded, so + // pressing Cancel looked like it did nothing at all (#138). + const [cancelNote, setCancelNote] = useState(null); const cancelMutation = useMutation({ - mutationFn: () => firmwareApi.cancelRollout(rolloutId), - onSuccess: () => qc.invalidateQueries({ queryKey: ['fw-rollout', rolloutId] }), + mutationFn: () => firmwareApi.cancelRollout(rolloutId).then(r => r.data), + onSuccess: (data) => { + setCancelNote( + data?.note ?? 'Rollout cancelled. No further devices will be upgraded.' + ); + qc.invalidateQueries({ queryKey: ['fw-rollout', rolloutId] }); + }, + onError: (e: unknown) => { + const err = e as { response?: { data?: { error?: string } } }; + setCancelNote(err.response?.data?.error ?? 'Could not cancel the rollout.'); + }, }); if (!rollout) return null; @@ -75,14 +88,22 @@ function RolloutPanel({ rolloutId, canWrite }: { rolloutId: number; canWrite: bo {rollout.halt_on_failure && halt on failure} {rollout.routerboot_after && + RouterBOOT} {canWrite && active && ( - )} + {cancelNote && ( +

+ + {cancelNote} +
+ )} + {waves.map(w => (
diff --git a/frontend/src/services/api.ts b/frontend/src/services/api.ts index 0c87322..114af6a 100644 --- a/frontend/src/services/api.ts +++ b/frontend/src/services/api.ts @@ -918,7 +918,8 @@ export const firmwareApi = { getRollout: (id: number) => api.get(`/firmware/rollouts/${id}`), startRollout: (id: number) => api.post(`/firmware/rollouts/${id}/start`), - cancelRollout: (id: number) => api.post(`/firmware/rollouts/${id}/cancel`), + cancelRollout: (id: number) => + api.post<{ ok: boolean; note?: string }>(`/firmware/rollouts/${id}/cancel`), changelog: (version: string) => api.get<{ version: string; url: string; text: string }>(`/firmware/changelog/${encodeURIComponent(version)}`), }; diff --git a/frontend/src/version.ts b/frontend/src/version.ts index 21f52de..c2458a5 100644 --- a/frontend/src/version.ts +++ b/frontend/src/version.ts @@ -1 +1 @@ -export const APP_VERSION = 'v0.24.0 Beta'; +export const APP_VERSION = 'v0.24.1 Beta';