fix: place log events in real time, reset the data cap on send, export runs (v0.23.29-beta)

Three reports from this morning. **Event timestamps were not the times the events happened.** RouterOS writes log times in the device's own timezone and never says so, and it uses more than one format. The parser handled `sep/03 08:37:38` and `08:37:38` but labelled both UTC, shifting every event by the device's offset — reported as an event log seven hours out from the device page. It did not handle `2026-09-03 08:37:38` at all, which is what current RouterOS actually returns over the API, so those fell through to the collection time instead: plausible on a live poll, badly wrong for a backlog, where a thousand historical lines all arrive stamped "now". Devices now report their clock, and timestamps are converted from device-local to UTC through it, with the numeric gmt-offset as a fallback and daylight saving handled by the runtime rather than a fixed number. Where the zone is unknown the parser returns null and the caller falls back to collection time, deliberately — a confidently wrong timestamp is worse than an openly approximate one. Verified on hardware: 18 of 18 events in a steady-state window now store exactly seven hours ahead of what the device printed, which is the offset the device itself reports. Existing rows are left alone; they were written by three different code paths and cannot be corrected uniformly. **The data-cap counter kept climbing after the SMS was sent.** Reported from the field, and correct: the message is what zeroes the carrier's allowance — it is the alternative to waiting for midnight — so ours has to follow. Left as it was, two things went wrong: the bar counted against an allowance that no longer applied, and usage stayed above the threshold, so the rule would re-fire on every cooldown for the rest of the day. Both send paths now restart the count. **Command runs export to CSV**, asked for on #118 for archiving and audit. Output is quoted so multi-line device responses survive, and timestamps are ISO rather than the driver's default string form, which no spreadsheet parses. The download goes through the authenticated client rather than a plain link, because a link cannot carry a Bearer header and would simply 401. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
2026-09-03 08:50:01 -07:00
parent cce1f88a45
commit 324ceba676
13 changed files with 374 additions and 49 deletions
@@ -712,6 +712,14 @@ CREATE TABLE IF NOT EXISTS wireless_security_profiles (
 -- remembering the answer.
 ALTER TABLE devices ADD COLUMN IF NOT EXISTS has_lte BOOLEAN NOT NULL DEFAULT FALSE;

+-- The device's own clock settings (#117).
+--
+-- RouterOS writes log timestamps in the device's local time and never says so.
+-- Without knowing the zone, an event can only be stored at the moment it was
+-- collected — which looks right on a live poll and is badly wrong for a backlog.
+ALTER TABLE devices ADD COLUMN IF NOT EXISTS time_zone_name VARCHAR(64);
+ALTER TABLE devices ADD COLUMN IF NOT EXISTS gmt_offset VARCHAR(16);
+
 -- Latest state of each LTE interface. One row per interface, overwritten on each
 -- poll; the time series lives in InfluxDB and the movement history below.
 --
@@ -149,6 +149,56 @@ router.get('/runs/:id', async (req: Request, res: Response) => {
  res.json({ ...run, devices });
 });

+/**
+ * GET /api/commands/runs/:id/export — the run as a downloadable record.
+ *
+ * Asked for on #118 for archiving and audit. CSV rather than JSON because the
+ * audience is a spreadsheet or a ticket attachment, and output is quoted so a
+ * multi-line device response survives the round trip intact.
+ */
+router.get('/runs/:id/export', async (req: Request, res: Response) => {
+  const run = await queryOne<{ id: number; name: string; command: string; status: string; created_at: string }>(
+    `SELECT id, name, command, status, created_at FROM command_runs WHERE id = $1`, [req.params.id]
+  );
+  if (!run) return res.status(404).json({ error: 'Run not found' });
+
+  const rows = await query<{
+    device_name: string; ip_address: string; wave: number; status: string;
+    output: string | null; error: string | null; guarded: boolean;
+    started_at: string | null; finished_at: string | null;
+  }>(
+    `SELECT d.name AS device_name, d.ip_address, rd.wave, rd.status, rd.output, rd.error,
+            rd.guarded, rd.started_at, rd.finished_at
+       FROM command_run_devices rd JOIN devices d ON d.id = rd.device_id
+      WHERE rd.run_id = $1 ORDER BY rd.wave, d.name`,
+    [req.params.id]
+  );
+
+  // Timestamps arrive from the driver as Date objects, whose default string form
+  // ("Thu Sep 03 2026 15:45:29 GMT+0000 (Coordinated Universal Time)") no
+  // spreadsheet will parse. ISO is both sortable and machine-readable.
+  const esc = (v: unknown) => {
+    const t = v == null ? '' : v instanceof Date ? v.toISOString() : String(v);
+    // Always quote: output routinely contains commas, quotes and newlines, and
+    // a record that cannot be reopened is not an archive.
+    return `"${t.replace(/"/g, '""')}"`;
+  };
+
+  const lines = [
+    ['run_id', 'run_name', 'command', 'run_status', 'device', 'ip_address', 'wave',
+     'status', 'guarded', 'started_at', 'finished_at', 'output', 'error'].join(','),
+    ...rows.map((r) => [
+      run.id, run.name, run.command, run.status, r.device_name.trim(), r.ip_address, r.wave,
+      r.status, r.guarded, r.started_at ?? '', r.finished_at ?? '', r.output ?? '', r.error ?? '',
+    ].map(esc).join(',')),
+  ];
+
+  const stamp = new Date(run.created_at).toISOString().slice(0, 19).replace(/[:T]/g, '-');
+  res.setHeader('Content-Type', 'text/csv; charset=utf-8');
+  res.setHeader('Content-Disposition', `attachment; filename="command-run-${run.id}-${stamp}.csv"`);
+  res.send(lines.join('\n'));
+});
+
 // POST /api/commands/runs/:id/start
 router.post('/runs/:id/start', requireWrite, async (req: Request, res: Response) => {
  try {
@@ -2545,8 +2545,10 @@ router.post('/:id/lte/data-cap/:iface/send', requireWrite, async (req: Request,
       VALUES ($1,$2,'manual',$3,$4,TRUE)`,
      [deviceRow.id, req.params.iface, phone, rule ? Number(rule.period_bytes) : null]
    ).catch(() => {});
+    // The counter restarts with the carrier's, for the same reason the automatic
+    // path resets it: the message is what zeroes their allowance.
    await query(
-      `UPDATE lte_data_cap_rules SET last_sent_at = NOW()
+      `UPDATE lte_data_cap_rules SET last_sent_at = NOW(), period_bytes = 0
        WHERE device_id = $1 AND interface_name = $2`,
      [deviceRow.id, req.params.iface]
    ).catch(() => {});
@@ -17,6 +17,7 @@ import {
  parseLteMonitor, overallQuality, detectChanges, type LteStatus,
 } from '../../utils/lte';
 import { bytesSince, periodKey, shouldSend } from '../../utils/dataCap';
+import { parseDeviceLogTime } from '../../utils/deviceTime';
 import { BackupService } from '../BackupService';
 import { alertService } from '../AlertService';

@@ -195,6 +196,8 @@ export class DeviceCollector {
      const identity = await this.client.execute('/system/identity/print');
      const resource = await this.client.execute('/system/resource/print');
      const routerboard = await this.client.execute('/system/routerboard/print').catch(() => [] as Record<string, string>[]);
+      // Needed to place log timestamps correctly — they are device-local (#117).
+      const clock = await this.client.execute('/system/clock/print').catch(() => [] as Record<string, string>[]);

      const info = resource[0] || {};
      const rb = routerboard[0] || {};
@@ -212,6 +215,8 @@ export class DeviceCollector {
          serial_number = COALESCE($3, serial_number),
          firmware_version = COALESCE($4, firmware_version),
          ros_version = COALESCE($5, ros_version),
+          time_zone_name = COALESCE($7, time_zone_name),
+          gmt_offset = COALESCE($8, gmt_offset),
          -- An update that has landed is no longer pending. The dedicated
          -- firmware check only runs once a day, so without this a device stays
          -- flagged "update available" for up to 24 hours after it has already
@@ -224,7 +229,8 @@ export class DeviceCollector {
          END,
          updated_at = NOW()
        WHERE id = $6`,
-        [identityName, model, serial, firmware, rosVersion, this.device.id]
+        [identityName, model, serial, firmware, rosVersion, this.device.id,
+         clock[0]?.['time-zone-name'] || null, clock[0]?.['gmt-offset'] || null]
      );
    } catch (err) {
      console.error(`[${this.device.name}] Failed to collect system info:`, err);
@@ -843,41 +849,19 @@ export class DeviceCollector {
    }
  }

+  /**
+   * A log timestamp as a real instant, using the device's own clock.
+   *
+   * Falls back to the collection time only when the device timezone is unknown
+   * or the format is unrecognised — approximate, but never confidently wrong by
+   * a whole timezone, which is what the previous version was (#117).
+   */
  private parseLogTime(timeStr: string): Date {
-    // RouterOS log time formats:
-    //   "jan/01 00:00:05"       — month/day only (no year) → default to current year
-    //   "jan/01/2024 00:00:05"  — full date with year
-    //   "00:00:05"              — time only (today, e.g. device uptime < 1 day)
-    if (!timeStr) return new Date();
-    try {
-      if (timeStr.includes('/')) {
-        const spaceIdx = timeStr.lastIndexOf(' ');
-        if (spaceIdx === -1) return new Date();
-        const datePart = timeStr.substring(0, spaceIdx);
-        const timePart = timeStr.substring(spaceIdx + 1);
-        const parts = datePart.split('/');
-        const monthStr = parts[0];
-        const day = parts[1];
-        if (!monthStr || !day) return new Date();
-        const year = parts[2] !== undefined ? parts[2] : String(new Date().getFullYear());
-        const months: Record<string, string> = {
-          jan: '01', feb: '02', mar: '03', apr: '04', may: '05', jun: '06',
-          jul: '07', aug: '08', sep: '09', oct: '10', nov: '11', dec: '12',
-        };
-        const month = months[monthStr.toLowerCase()] || '01';
-        const d = new Date(`${year}-${month}-${day.padStart(2, '0')}T${timePart}Z`);
-        if (isNaN(d.getTime())) return new Date();
-        return d;
-      } else {
-        // Time only (today)
-        const today = new Date().toISOString().split('T')[0];
-        const d = new Date(`${today}T${timeStr}Z`);
-        if (isNaN(d.getTime())) return new Date();
-        return d;
-      }
-    } catch {
-      return new Date();
-    }
+    const d = this.device as unknown as { time_zone_name?: string | null; gmt_offset?: string | null };
+    const parsed = parseDeviceLogTime(timeStr, {
+      timeZoneName: d.time_zone_name, gmtOffset: d.gmt_offset,
+    });
+    return parsed ?? new Date();
  }

  private mapLogSeverity(topics: string): string {
@@ -3088,10 +3072,17 @@ export class DeviceCollector {
      }, now);

      let sentAt: Date | null = rolled ? null : (rule.last_sent_at ? new Date(rule.last_sent_at) : null);
+      // Sending the reset SMS zeroes the carrier's counter — that is what the
+      // message is for, and it is the alternative to waiting for midnight. Our
+      // counter has to follow, or two things go wrong: the bar keeps climbing
+      // past an allowance that no longer applies, and usage stays above the
+      // threshold so the rule re-fires on every cooldown for the rest of the day.
+      let periodBytesAfter = periodBytes;
      if (decision.send) {
        try {
          await this.sendSms(interfaceName, rule.phone_number, rule.message);
          sentAt = now;
+          periodBytesAfter = 0;
          await this.logDataCapSend(interfaceName, 'threshold', rule.phone_number, periodBytes, true, null);
          console.log(`[DataCap] ${this.device.name}/${interfaceName}: reset SMS sent to ${rule.phone_number}`);
        } catch (e) {
@@ -3105,7 +3096,7 @@ export class DeviceCollector {
            SET period_key = $2, period_bytes = $3, last_rx = $4, last_tx = $5,
                last_sent_at = $6, updated_at = NOW()
          WHERE id = $1`,
-        [rule.id, key, periodBytes, counters.rxBytes, counters.txBytes, sentAt]
+        [rule.id, key, periodBytesAfter, counters.rxBytes, counters.txBytes, sentAt]
      );
    } catch (e) {
      console.error(`[DataCap] ${this.device.name}: tracking failed:`, (e as Error).message);
@@ -0,0 +1,100 @@
+import {
+  parseDeviceLogTime, parseWallClock, wallClockToUtc, parseGmtOffsetMs,
+} from '../deviceTime';
+
+const NOW = new Date('2026-09-03T15:37:45Z');
+const LA = { timeZoneName: 'America/Los_Angeles' };   // UTC-7 in September
+const JAKARTA = { timeZoneName: 'Asia/Jakarta' };     // UTC+7, no DST
+
+describe('parseWallClock', () => {
+  it('reads the space-separated form current RouterOS returns', () => {
+    // This one was not handled at all, so every such timestamp silently became
+    // the moment of collection instead of the moment of the event.
+    expect(parseWallClock('2026-09-03 08:37:38', NOW))
+      .toEqual({ y: 2026, mo: 9, d: 3, h: 8, mi: 37, s: 38 });
+  });
+
+  it('reads the month-name forms, with and without a year', () => {
+    expect(parseWallClock('sep/03/2026 08:37:38', NOW))
+      .toEqual({ y: 2026, mo: 9, d: 3, h: 8, mi: 37, s: 38 });
+    expect(parseWallClock('sep/03 08:37:38', NOW))
+      .toEqual({ y: 2026, mo: 9, d: 3, h: 8, mi: 37, s: 38 });
+  });
+
+  it('reads a bare time as today', () => {
+    expect(parseWallClock('08:37:38', NOW))
+      .toEqual({ y: 2026, mo: 9, d: 3, h: 8, mi: 37, s: 38 });
+  });
+
+  it('returns null rather than guessing at nonsense', () => {
+    expect(parseWallClock('', NOW)).toBeNull();
+    expect(parseWallClock('yesterday', NOW)).toBeNull();
+    expect(parseWallClock('xyz/03 08:37:38', NOW)).toBeNull();
+  });
+});
+
+describe('wallClockToUtc', () => {
+  it('converts device-local wall clock to the instant it names', () => {
+    // 08:37 in Los Angeles during September is 15:37 UTC.
+    expect(wallClockToUtc(2026, 9, 3, 8, 37, 38, 'America/Los_Angeles').toISOString())
+      .toBe('2026-09-03T15:37:38.000Z');
+  });
+
+  it('handles a zone ahead of UTC', () => {
+    expect(wallClockToUtc(2026, 9, 3, 15, 0, 0, 'Asia/Jakarta').toISOString())
+      .toBe('2026-09-03T08:00:00.000Z');
+  });
+
+  it('respects daylight saving rather than a fixed offset', () => {
+    // Same wall clock, six months apart: PDT (-7) then PST (-8).
+    expect(wallClockToUtc(2026, 7, 1, 12, 0, 0, 'America/Los_Angeles').toISOString())
+      .toBe('2026-07-01T19:00:00.000Z');
+    expect(wallClockToUtc(2026, 1, 1, 12, 0, 0, 'America/Los_Angeles').toISOString())
+      .toBe('2026-01-01T20:00:00.000Z');
+  });
+});
+
+describe('parseGmtOffsetMs', () => {
+  it('reads the forms RouterOS uses', () => {
+    expect(parseGmtOffsetMs('-07:00')).toBe(-7 * 3600_000);
+    expect(parseGmtOffsetMs('+05:30')).toBe(5.5 * 3600_000);
+    expect(parseGmtOffsetMs('+0700')).toBe(7 * 3600_000);
+    expect(parseGmtOffsetMs('25200')).toBe(7 * 3600_000);
+  });
+  it('returns null for nothing usable', () => {
+    expect(parseGmtOffsetMs(null)).toBeNull();
+    expect(parseGmtOffsetMs('')).toBeNull();
+    expect(parseGmtOffsetMs('somewhere')).toBeNull();
+  });
+});
+
+describe('parseDeviceLogTime — the reported bug', () => {
+  it('does not shift an event by the device offset', () => {
+    // Reported as the event log reading seven hours later than the device page.
+    // A device in UTC+7 logging 15:00 means 08:00 UTC, not 15:00 UTC.
+    expect(parseDeviceLogTime('sep/03 15:00:00', JAKARTA, NOW)!.toISOString())
+      .toBe('2026-09-03T08:00:00.000Z');
+  });
+
+  it('places the space-separated form correctly too', () => {
+    expect(parseDeviceLogTime('2026-09-03 08:37:38', LA, NOW)!.toISOString())
+      .toBe('2026-09-03T15:37:38.000Z');
+  });
+
+  it('falls back to the numeric offset when the zone name is unusable', () => {
+    expect(parseDeviceLogTime('2026-09-03 08:37:38', { gmtOffset: '-07:00' }, NOW)!.toISOString())
+      .toBe('2026-09-03T15:37:38.000Z');
+    expect(parseDeviceLogTime('2026-09-03 08:37:38', { timeZoneName: 'Nowhere/Real', gmtOffset: '-07:00' }, NOW)!.toISOString())
+      .toBe('2026-09-03T15:37:38.000Z');
+  });
+
+  it('returns null when the device timezone is unknown', () => {
+    // Deliberately: the caller decides what to do. A confidently wrong
+    // timestamp is worse than an openly approximate one.
+    expect(parseDeviceLogTime('2026-09-03 08:37:38', {}, NOW)).toBeNull();
+  });
+
+  it('returns null for an unparseable timestamp', () => {
+    expect(parseDeviceLogTime('not a time', LA, NOW)).toBeNull();
+  });
+});
@@ -0,0 +1,142 @@
+/**
+ * Turning a RouterOS log timestamp into a real instant.
+ *
+ * RouterOS writes log times in the **device's own timezone** and never says so.
+ * Treating them as UTC shifts every event by the device's offset — reported as
+ * an event log seven hours out from the device page (#117).
+ *
+ * It also uses more than one format. A device may report any of:
+ *
+ *   2026-09-03 08:37:38     full date, space separated
+ *   sep/03/2026 08:37:38    month name, with year
+ *   sep/03 08:37:38         month name, no year
+ *   08:37:38                time only, for entries from today
+ *
+ * The space-separated form was not handled at all, so those timestamps silently
+ * became the moment of collection rather than the moment of the event — which
+ * looks correct on a live poll and is badly wrong for any backlog, where a
+ * thousand historical lines all arrive stamped "now".
+ */
+
+const MONTHS: Record<string, number> = {
+  jan: 1, feb: 2, mar: 3, apr: 4, may: 5, jun: 6,
+  jul: 7, aug: 8, sep: 9, oct: 10, nov: 11, dec: 12,
+};
+
+/** Offset of a zone, in milliseconds, at a given instant. */
+function offsetMsAt(utcMs: number, timeZone: string): number {
+  const parts = Object.fromEntries(
+    new Intl.DateTimeFormat('en-US', {
+      timeZone, hour12: false,
+      year: 'numeric', month: '2-digit', day: '2-digit',
+      hour: '2-digit', minute: '2-digit', second: '2-digit',
+    }).formatToParts(new Date(utcMs)).map((p) => [p.type, p.value])
+  );
+  const asIfUtc = Date.UTC(
+    Number(parts.year), Number(parts.month) - 1, Number(parts.day),
+    Number(parts.hour) % 24, Number(parts.minute), Number(parts.second),
+  );
+  return asIfUtc - utcMs;
+}
+
+/**
+ * Wall-clock fields in a named zone → the UTC instant they describe.
+ *
+ * Two passes, because the offset depends on the instant and the instant depends
+ * on the offset. The second pass settles daylight-saving boundaries, where the
+ * first guess can land on the wrong side of a transition.
+ */
+export function wallClockToUtc(
+  y: number, mo: number, d: number, h: number, mi: number, s: number, timeZone: string,
+): Date {
+  const guess = Date.UTC(y, mo - 1, d, h, mi, s);
+  let offset = offsetMsAt(guess, timeZone);
+  offset = offsetMsAt(guess - offset, timeZone);
+  return new Date(guess - offset);
+}
+
+/** Wall-clock fields pulled out of a log timestamp, before any zone is applied. */
+interface WallClock { y: number; mo: number; d: number; h: number; mi: number; s: number }
+
+/** Split a RouterOS timestamp into wall-clock fields. Null when unrecognised. */
+export function parseWallClock(timeStr: string, now: Date): WallClock | null {
+  const t = (timeStr || '').trim();
+  if (!t) return null;
+
+  // 2026-09-03 08:37:38  — what current RouterOS returns over the API.
+  let m = t.match(/^(\d{4})-(\d{2})-(\d{2})[ T](\d{1,2}):(\d{2}):(\d{2})/);
+  if (m) {
+    return { y: +m[1], mo: +m[2], d: +m[3], h: +m[4], mi: +m[5], s: +m[6] };
+  }
+
+  // sep/03/2026 08:37:38  or  sep/03 08:37:38
+  m = t.match(/^([a-z]{3})\/(\d{1,2})(?:\/(\d{4}))?\s+(\d{1,2}):(\d{2}):(\d{2})/i);
+  if (m) {
+    const mo = MONTHS[m[1].toLowerCase()];
+    if (!mo) return null;
+    return {
+      // Without a year RouterOS means the current one on the device.
+      y: m[3] ? +m[3] : now.getUTCFullYear(),
+      mo, d: +m[2], h: +m[4], mi: +m[5], s: +m[6],
+    };
+  }
+
+  // 08:37:38 — today, on the device.
+  m = t.match(/^(\d{1,2}):(\d{2}):(\d{2})$/);
+  if (m) {
+    return {
+      y: now.getUTCFullYear(), mo: now.getUTCMonth() + 1, d: now.getUTCDate(),
+      h: +m[1], mi: +m[2], s: +m[3],
+    };
+  }
+  return null;
+}
+
+export interface DeviceClock {
+  /** IANA name from /system/clock, e.g. "America/Los_Angeles". */
+  timeZoneName?: string | null;
+  /** RouterOS gmt-offset, e.g. "-07:00". Used when the zone name is unusable. */
+  gmtOffset?: string | null;
+}
+
+/** RouterOS gmt-offset ("-07:00", "+0530", "25200") to milliseconds. */
+export function parseGmtOffsetMs(raw: string | null | undefined): number | null {
+  if (!raw) return null;
+  const t = String(raw).trim();
+  const m = t.match(/^([+-])(\d{1,2}):?(\d{2})$/);
+  if (m) {
+    const ms = (Number(m[2]) * 3600 + Number(m[3]) * 60) * 1000;
+    return m[1] === '-' ? -ms : ms;
+  }
+  const secs = Number(t);
+  return Number.isFinite(secs) ? secs * 1000 : null;
+}
+
+/**
+ * A RouterOS log timestamp as a real instant.
+ *
+ * Returns null when the format is unrecognised *or* the device's timezone is
+ * unknown — deliberately, so the caller decides rather than this guessing. A
+ * wrong timestamp is worse than an obviously approximate one, because it looks
+ * authoritative.
+ */
+export function parseDeviceLogTime(
+  timeStr: string, clock: DeviceClock, now = new Date(),
+): Date | null {
+  const wall = parseWallClock(timeStr, now);
+  if (!wall) return null;
+
+  if (clock.timeZoneName) {
+    try {
+      return wallClockToUtc(wall.y, wall.mo, wall.d, wall.h, wall.mi, wall.s, clock.timeZoneName);
+    } catch {
+      // Fall through to the numeric offset below.
+    }
+  }
+
+  const offsetMs = parseGmtOffsetMs(clock.gmtOffset);
+  if (offsetMs != null) {
+    return new Date(Date.UTC(wall.y, wall.mo - 1, wall.d, wall.h, wall.mi, wall.s) - offsetMs);
+  }
+  return null;
+}